feat: add trace logging with an id to reconstruct chain of events

Author: AntoineGS

lua/copilot/api.lua

@@ -1,10 +1,12 @@
+local logger = require("copilot.logger")
 local mod = {}
 
 ---@param callback? fun(err: any|nil, data: table, ctx: table): nil
 ---@return any|nil err
 ---@return table data
 ---@return table ctx
 function mod.request(client, method, params, callback)
+  logger.trace("api request:", method, params)
   -- hack to convert empty table to json object,
   -- empty table is convert to json array by default.
   params._ = true
@@ -25,6 +27,7 @@ end
 
 ---@return boolean sent
 function mod.notify(client, method, params)
+  logger.trace("api notify:", method, params)
   return client.notify(method, params)
 end
 

lua/copilot/logger.lua

@@ -5,6 +5,7 @@ local mod = {
   log_file = vim.fn.stdpath("log") .. "/copilot-lua.log",
   file_log_level = vim.log.levels.OFF,
   print_log_level = vim.log.levels.WARN,
+  logger_id = 0,
 }
 
 local log_level_names = {
@@ -24,33 +25,41 @@ end
 
 ---@param log_level integer --vim.log.levels
 ---@param msg string
----@param data any
+---@param ... any
 ---@return string log_msg
-local function format_log(log_level, msg, data)
+local function format_log(log_level, msg, ...)
   local log_level_name = log_level_names[log_level]
-  local log_msg = string.format("%s [%s]: %s", get_timestamp_with_ms(), log_level_name, msg)
+  mod.logger_id = mod.logger_id + 1
 
-  if data then
-    log_msg = string.format("%s\n%s", log_msg, vim.inspect(data))
+  if mod.logger_id > 1000000 then
+    mod.logger_id = 1
+  end
+
+  -- we add an id as this process is asynchronous and the logs end up in a different order
+  local log_msg = string.format("%s [%d] [%s]: %s", get_timestamp_with_ms(), mod.logger_id, log_level_name, msg)
+
+  local args = { ... }
+  for _, v in ipairs(args) do
+    log_msg = string.format("%s\n%s", log_msg, vim.inspect(v))
   end
 
   return log_msg
 end
 
 ---@param log_level integer -- one of the vim.log.levels
 ---@param msg string
----@param data any
-local function notify_log(log_level, msg, data)
-  local log_msg = format_log(log_level, msg, data)
+---@param ... any
+local function notify_log(log_level, msg, ...)
+  local log_msg = format_log(log_level, msg, ...)
   vim.notify(log_msg, log_level)
 end
 
 ---@param log_level integer -- one of the vim.log.levels
 ---@param log_file string
 ---@param msg string
----@param data any
-local function write_log(log_level, log_file, msg, data)
-  local log_msg = format_log(log_level, msg, data) .. "\n"
+---@param ... any
+local function write_log(log_level, log_file, msg, ...)
+  local log_msg = format_log(log_level, msg, ...) .. "\n"
 
   uv.fs_open(log_file, "a", tonumber("644", 8), function(err, fd)
     if err then
@@ -70,52 +79,59 @@ end
 
 ---@param log_level integer -- one of the vim.log.levels
 ---@param msg string
----@param data any
+---@param ... any
+function mod.log(log_level, msg, ...)
+  mod.log_force(log_level, msg, false, ...)
+end
+
+---@param log_level integer -- one of the vim.log.levels
+---@param msg string
+---@param ... any
 ---@param force_print boolean
-function mod.log(log_level, msg, data, force_print)
+function mod.log_force(log_level, msg, force_print, ...)
   if mod.file_log_level <= log_level then
-    write_log(log_level, mod.log_file, msg, data)
+    write_log(log_level, mod.log_file, msg, ...)
   end
 
   if force_print or (mod.print_log_level <= log_level) then
-    notify_log(log_level, msg, data)
+    notify_log(log_level, msg, ...)
   end
 end
 
 ---@param msg string
----@param data any
-function mod.debug(msg, data)
-  mod.log(vim.log.levels.DEBUG, msg, data, false)
+---@param ... any
+function mod.debug(msg, ...)
+  mod.log(vim.log.levels.DEBUG, msg, ...)
 end
 
 ---@param msg string
----@param data any
-function mod.trace(msg, data)
-  mod.log(vim.log.levels.TRACE, msg, data, false)
+---@param ... any
+function mod.trace(msg, ...)
+  mod.log(vim.log.levels.TRACE, msg, ...)
 end
 
 ---@param msg string
----@param data any
-function mod.error(msg, data)
-  mod.log(vim.log.levels.ERROR, msg, data, false)
+---@param ... any
+function mod.error(msg, ...)
+  mod.log(vim.log.levels.ERROR, msg, ...)
 end
 
 ---@param msg string
----@param data any
-function mod.warn(msg, data)
-  mod.log(vim.log.levels.WARN, msg, data, false)
+---@param ... any
+function mod.warn(msg, ...)
+  mod.log(vim.log.levels.WARN, msg, ...)
 end
 
 ---@param msg string
----@param data any
-function mod.info(msg, data)
-  mod.log(vim.log.levels.INFO, msg, data, false)
+---@param ... any
+function mod.info(msg, ...)
+  mod.log(vim.log.levels.INFO, msg, ...)
 end
 
 ---@param msg string
----@param data any
-function mod.notify(msg, data)
-  mod.log(vim.log.levels.INFO, msg, data, true)
+---@param ... any
+function mod.notify(msg, ...)
+  mod.log_force(vim.log.levels.INFO, msg, true, ...)
 end
 
 ---@param conf copilot_config_logging

lua/copilot/suggestion.lua

@@ -51,15 +51,18 @@ end
 local function get_ctx(bufnr)
   bufnr = bufnr or vim.api.nvim_get_current_buf()
   local ctx = copilot.context[bufnr]
+  logger.trace("suggestion context", ctx)
   if not ctx then
     ctx = {}
     copilot.context[bufnr] = ctx
+    logger.trace("suggestion new context", ctx)
   end
   return ctx
 end
 
 ---@param ctx copilot_suggestion_context
 local function reset_ctx(ctx)
+  logger.trace("suggestion reset context", ctx)
   ctx.first = nil
   ctx.cycling = nil
   ctx.cycling_callbacks = nil
@@ -149,6 +152,7 @@ end
 
 local function stop_timer()
   if copilot._copilot_timer then
+    logger.trace("suggestion stop timer")
     vim.fn.timer_stop(copilot._copilot_timer)
     copilot._copilot_timer = nil
   end
@@ -172,28 +176,34 @@ end
 
 ---@param ctx? copilot_suggestion_context
 local function cancel_inflight_requests(ctx)
+  logger.trace("suggestion cancel inflight requests", ctx)
   ctx = ctx or get_ctx()
 
   with_client(function(client)
     if ctx.first then
       client.cancel_request(ctx.first)
       ctx.first = nil
+      logger.trace("suggestion cancel first request")
     end
     if ctx.cycling then
       client.cancel_request(ctx.cycling)
       ctx.cycling = nil
+      logger.trace("suggestion cancel cycling request")
     end
   end)
 end
 
 local function clear_preview()
+  logger.trace("suggestion clear preview")
   vim.api.nvim_buf_del_extmark(0, copilot.ns_id, copilot.extmark_id)
 end
 
 ---@param ctx? copilot_suggestion_context
 ---@return copilot_get_completions_data_completion|nil
 local function get_current_suggestion(ctx)
+  logger.trace("suggestion get current suggestion", ctx)
   ctx = ctx or get_ctx()
+  logger.trace("suggestion current suggestion", ctx)
 
   local ok, choice = pcall(function()
     if
@@ -229,6 +239,7 @@ end
 ---@param ctx? copilot_suggestion_context
 local function update_preview(ctx)
   ctx = ctx or get_ctx()
+  logger.trace("suggestion update preview", ctx)
 
   local suggestion = get_current_suggestion(ctx)
   local displayLines = suggestion and vim.split(suggestion.displayText, "\n", { plain = true }) or {}
@@ -286,6 +297,7 @@ end
 
 ---@param ctx? copilot_suggestion_context
 local function clear(ctx)
+  logger.trace("suggestion clear", ctx)
   ctx = ctx or get_ctx()
   stop_timer()
   cancel_inflight_requests(ctx)
@@ -295,6 +307,7 @@ end
 
 ---@param callback fun(err: any|nil, data: copilot_get_completions_data): nil
 local function complete(callback)
+  logger.trace("suggestion complete")
   stop_timer()
 
   local ctx = get_ctx()
@@ -314,6 +327,7 @@ local function handle_trigger_request(err, data)
   if err then
     logger.error(err)
   end
+  logger.trace("suggestion handle trigger request", data)
   local ctx = get_ctx()
   ctx.suggestions = data and data.completions or {}
   ctx.choice = 1
@@ -322,10 +336,12 @@ local function handle_trigger_request(err, data)
 end
 
 local function trigger(bufnr, timer)
+  logger.trace("suggestion trigger", bufnr)
   local _timer = copilot._copilot_timer
   copilot._copilot_timer = nil
 
   if bufnr ~= vim.api.nvim_get_current_buf() or (_timer ~= nil and timer ~= _timer) or vim.fn.mode() ~= "i" then
+    logger.trace("suggestion trigger, not in insert mode")
     return
   end
 
@@ -334,6 +350,7 @@ end
 
 ---@param ctx copilot_suggestion_context
 local function get_suggestions_cycling_callback(ctx, err, data)
+  logger.trace("suggestion get suggestions cycling callback", data)
   local callbacks = ctx.cycling_callbacks or {}
   ctx.cycling_callbacks = nil
 
@@ -367,6 +384,8 @@ end
 ---@param callback fun(ctx: copilot_suggestion_context): nil
 ---@param ctx copilot_suggestion_context
 local function get_suggestions_cycling(callback, ctx)
+  logger.trace("suggestion get suggestions cycling", ctx)
+
   if ctx.cycling_callbacks then
     table.insert(ctx.cycling_callbacks, callback)
     return
@@ -407,19 +426,23 @@ local function schedule(ctx)
     clear()
     return
   end
+  logger.trace("suggestion schedule", ctx)
 
   update_preview(ctx)
   local bufnr = vim.api.nvim_get_current_buf()
   copilot._copilot_timer = vim.fn.timer_start(copilot.debounce, function(timer)
+    logger.trace("suggestion schedule timer", bufnr)
     trigger(bufnr, timer)
   end)
 end
 
 function mod.next()
   local ctx = get_ctx()
+  logger.trace("suggestion next", ctx)
 
   -- no suggestion request yet
   if not ctx.first then
+    logger.trace("suggestion next, no first request")
     schedule(ctx)
     return
   end
@@ -431,9 +454,11 @@ end
 
 function mod.prev()
   local ctx = get_ctx()
+  logger.trace("suggestion prev", ctx)
 
   -- no suggestion request yet
   if not ctx.first then
+    logger.trace("suggestion prev, no first request", ctx)
     schedule(ctx)
     return
   end
@@ -446,9 +471,11 @@ end
 ---@param modifier? (fun(suggestion: copilot_get_completions_data_completion): copilot_get_completions_data_completion)
 function mod.accept(modifier)
   local ctx = get_ctx()
+  logger.trace("suggestion accept", ctx)
 
   -- no suggestion request yet
   if not ctx.first then
+    logger.trace("suggestion accept, not first request", ctx)
     schedule(ctx)
     return
   end
@@ -466,7 +493,7 @@ function mod.accept(modifier)
   end
 
   with_client(function(client)
-    local ok, err = pcall(function()
+    local ok, _ = pcall(function()
       api.notify_accepted(
         client,
         { uuid = suggestion.uuid, acceptedLength = util.strutf16len(suggestion.text) },
@@ -568,6 +595,7 @@ end
 
 local function on_insert_enter()
   if should_auto_trigger() then
+    logger.trace("suggestion on insert enter")
     schedule()
   end
 end
@@ -581,13 +609,15 @@ end
 local function on_cursor_moved_i()
   local ctx = get_ctx()
   if copilot._copilot_timer or ctx.params or should_auto_trigger() then
+    logger.trace("suggestion on cursor moved insert")
     schedule(ctx)
   end
 end
 
 local function on_text_changed_p()
   local ctx = get_ctx()
   if not copilot.hide_during_completion and (copilot._copilot_timer or ctx.params or should_auto_trigger()) then
+    logger.trace("suggestion on text changed pum")
     schedule(ctx)
   end
 end