add logging for APIs.

Author: Zhe Yu

lua/vectorcode/cacher/default.lua

@@ -3,6 +3,8 @@ local M = {}
 local vc_config = require("vectorcode.config")
 local notify_opts = vc_config.notify_opts
 
+local logger = vc_config.logger
+
 ---@type table<integer, VectorCode.Cache>
 local CACHE = {}
 
@@ -25,6 +27,11 @@ local function async_runner(query_message, buf_nr)
   if CACHE[buf_nr] == nil or not CACHE[buf_nr].enabled then
     return
   end
+  local buf_name
+  vim.schedule(function()
+    buf_name = vim.api.nvim_buf_get_name(buf_nr)
+    logger.debug("Started default cacher job on :", buf_name)
+  end)
   ---@type VectorCode.Cache
   local cache = CACHE[buf_nr]
   local args = {
@@ -52,6 +59,7 @@ local function async_runner(query_message, buf_nr)
     vim.list_extend(args, { "--project_root", project_root })
   end
   CACHE[buf_nr].job_count = CACHE[buf_nr].job_count + 1
+  logger.debug("vectorcode default cacher job args: ", args)
   local job = require("plenary.job"):new({
     command = "vectorcode",
     args = args,
@@ -65,6 +73,7 @@ local function async_runner(query_message, buf_nr)
       if not M.buf_is_registered(buf_nr) then
         return
       end
+      logger.debug("vectorcode ", buf_name, " default cacher results: ", self:result())
       CACHE[buf_nr].job_count = CACHE[buf_nr].job_count - 1
       CACHE[buf_nr].jobs[self.pid] = nil
       local ok, json = pcall(
@@ -130,6 +139,12 @@ M.register_buffer = vc_config.check_cli_wrap(
     if bufnr == 0 or bufnr == nil then
       bufnr = vim.api.nvim_get_current_buf()
     end
+    logger.info(
+      ("Registering buffer %s %s for default cacher."):format(
+        bufnr,
+        vim.api.nvim_buf_get_name(bufnr)
+      )
+    )
     if M.buf_is_registered(bufnr) then
       opts = vim.tbl_deep_extend("force", CACHE[bufnr].options, opts or {})
     end
@@ -140,6 +155,12 @@ M.register_buffer = vc_config.check_cli_wrap(
       -- update the options and/or query_cb
       CACHE[bufnr].options =
         vim.tbl_deep_extend("force", CACHE[bufnr].options, opts or {})
+      logger.debug(
+        ("Updated `default` cacher opts for buffer %s:\n%s"):format(
+          bufnr,
+          vim.inspect(opts)
+        )
+      )
     else
       CACHE[bufnr] = {
         enabled = true,
@@ -196,6 +217,9 @@ M.deregister_buffer = vc_config.check_cli_wrap(
     if bufnr == nil or bufnr == 0 then
       bufnr = vim.api.nvim_get_current_buf()
     end
+    logger.info(
+      ("Deregistering buffer %s %s"):format(bufnr, vim.api.nvim_buf_get_name(bufnr))
+    )
     if M.buf_is_registered(bufnr) then
       kill_jobs(bufnr)
       vim.api.nvim_del_augroup_by_name(("VectorCodeCacheGroup%d"):format(bufnr))
@@ -244,13 +268,11 @@ M.query_from_cache = vc_config.check_cli_wrap(
         opts or {}
       )
       result = CACHE[bufnr].retrieval or {}
+      local message = ("Retrieved %d documents from cache."):format(#result)
+      logger.info(("vectorcode cmd cacher for buf %s: %s"):format(bufnr, message))
       if opts.notify then
         vim.schedule(function()
-          vim.notify(
-            ("Retrieved %d documents from cache."):format(#result),
-            vim.log.levels.INFO,
-            notify_opts
-          )
+          vim.notify(message, vim.log.levels.INFO, notify_opts)
         end)
       end
     end

lua/vectorcode/cacher/lsp.lua

@@ -1,6 +1,8 @@
 ---@type VectorCode.CacheBackend
 local M = {}
 local vc_config = require("vectorcode.config")
+local logger = vc_config.logger
+
 local notify_opts = vc_config.notify_opts
 
 local job_runner = require("vectorcode.jobrunner.lsp")
@@ -86,6 +88,11 @@ local function async_runner(query_message, buf_nr)
   if CACHE[buf_nr] == nil or not CACHE[buf_nr].enabled or not is_lsp_running() then
     return
   end
+  local buf_name
+  vim.schedule(function()
+    buf_name = vim.api.nvim_buf_get_name(buf_nr)
+    logger.debug("Started lsp cacher job on :", buf_name)
+  end)
   assert(client_id ~= nil)
   ---@type VectorCode.Cache
   local cache = CACHE[buf_nr]
@@ -127,8 +134,14 @@ local function async_runner(query_message, buf_nr)
       kill_jobs(buf_nr)
     end
     CACHE[buf_nr].job_count = CACHE[buf_nr].job_count + 1
+
+    logger.debug("vectorcode lsp cacher job args: ", args)
     local request_id = job_runner.run_async(args, function(result, err)
       CACHE[buf_nr].retrieval = result or CACHE[buf_nr].retrieval or {}
+      logger.debug("vectorcode ", buf_name, " lsp cacher results: ", result)
+      if err then
+        logger.debug("vectorcode ", buf_name, " lsp cacher error: ", err)
+      end
     end, buf_nr)
 
     if request_id ~= nil then
@@ -159,8 +172,21 @@ M.register_buffer = vc_config.check_cli_wrap(
     if bufnr == 0 or bufnr == nil then
       bufnr = vim.api.nvim_get_current_buf()
     end
+
+    logger.info(
+      ("Registering buffer %s %s for lsp cacher."):format(
+        bufnr,
+        vim.api.nvim_buf_get_name(bufnr)
+      )
+    )
     if M.buf_is_registered(bufnr) then
       opts = vim.tbl_deep_extend("force", CACHE[bufnr].options, opts or {})
+      logger.debug(
+        ("Updated `lsp` cacher opts for buffer %s:\n%s"):format(
+          bufnr,
+          vim.inspect(opts)
+        )
+      )
     end
     opts =
       vim.tbl_deep_extend("force", vc_config.get_user_config().async_opts, opts or {})
@@ -222,6 +248,9 @@ M.deregister_buffer = vc_config.check_cli_wrap(
     if bufnr == nil or bufnr == 0 then
       bufnr = vim.api.nvim_get_current_buf()
     end
+    logger.info(
+      ("Deregistering buffer %s %s"):format(bufnr, vim.api.nvim_buf_get_name(bufnr))
+    )
     if M.buf_is_registered(bufnr) then
       kill_jobs(bufnr)
       vim.api.nvim_del_augroup_by_name(("VectorCodeCacheGroup%d"):format(bufnr))
@@ -276,13 +305,11 @@ M.query_from_cache = vc_config.check_cli_wrap(
         opts or {}
       )
       result = CACHE[bufnr].retrieval or {}
+      local message = ("Retrieved %d documents from cache."):format(#result)
+      logger.info(("vectorcode cmd cacher for buf %s: %s"):format(bufnr, message))
       if opts.notify then
         vim.schedule(function()
-          vim.notify(
-            ("Retrieved %d documents from cache."):format(#result),
-            vim.log.levels.INFO,
-            notify_opts
-          )
+          vim.notify(message, vim.log.levels.INFO, notify_opts)
         end)
       end
     end

lua/vectorcode/config.lua

@@ -24,27 +24,43 @@ local config = {
   notify = true,
   timeout_ms = 5000,
   on_setup = { update = false, lsp = false },
+  sync_log_env_var = false,
 }
 
+local setup_config = vim.deepcopy(config, true)
+
 ---@return vim.lsp.ClientConfig
 local lsp_configs = function()
+  ---@type vim.lsp.ClientConfig
   local cfg =
     { cmd = { "vectorcode-server" }, root_markers = { ".vectorcode", ".git" } }
   if vim.lsp.config ~= nil and vim.lsp.config.vectorcode_server ~= nil then
     -- nvim >= 0.11.0
     cfg = vim.tbl_deep_extend("force", cfg, vim.lsp.config.vectorcode_server)
+    logger.debug("Using vim.lsp.config.vectorcode_server for LSP config:\n", cfg)
   else
     -- nvim < 0.11.0
     local ok, lspconfig = pcall(require, "lspconfig.configs")
     if ok and lspconfig.vectorcode_server ~= nil then
       cfg = lspconfig.vectorcode_server.config_def.default_config
+      logger.debug("Using nvim-lspconfig for LSP config:\n", cfg)
     end
   end
   cfg.name = "vectorcode_server"
+  if setup_config.sync_log_env_var then
+    local level = os.getenv("VECTORCODE_NVIM_LOG_LEVEL") or nil
+    if level ~= nil then
+      level = string.upper(level)
+      if level == "TRACE" then
+        -- there's no `TRACE` in python logging
+        level = "DEBUG"
+      end
+      cfg.cmd_env["VECTORCODE_LOG_LEVEL"] = level
+    end
+  end
   return cfg
 end
 
-local setup_config = vim.deepcopy(config, true)
 local notify_opts = { title = "VectorCode" }
 
 ---@param opts {notify:boolean}?
@@ -75,6 +91,7 @@ local startup_handler = check_cli_wrap(function(configs)
       if out.code == 0 then
         local path = string.gsub(out.stdout, "^%s*(.-)%s*$", "%1")
         if path ~= "" then
+          logger.info("Running `vectorcode update` on start up.")
           require("vectorcode").update(path)
         end
       end
@@ -84,6 +101,7 @@ local startup_handler = check_cli_wrap(function(configs)
     local ok, runner = pcall(require, "vectorcode.jobrunner.lsp")
     if not ok or not type(runner) == "table" or runner == nil then
       vim.notify("Failed to start vectorcode-server.", vim.log.levels.WARN, notify_opts)
+      logger.error("Failed to start vectorcode-server.")
       return
     end
     runner.init()
@@ -98,7 +116,7 @@ return {
   setup = check_cli_wrap(
     ---@param opts VectorCode.Opts?
     function(opts)
-      logger.info(opts)
+      logger.info("Received setup opts:\n", opts)
       opts = opts or {}
       setup_config = vim.tbl_deep_extend("force", config, opts or {})
       for k, v in pairs(setup_config.async_opts) do

lua/vectorcode/init.lua

@@ -1,6 +1,9 @@
 local M = {}
 
 local vc_config = require("vectorcode.config")
+
+local logger = vc_config.logger
+
 local get_config = vc_config.get_user_config
 
 local notify_opts = vc_config.notify_opts
@@ -15,6 +18,7 @@ M.query = vc_config.check_cli_wrap(
   ---@param callback fun(result:VectorCode.Result[])? Use the result async style.
   ---@return VectorCode.Result[]? An array of results.
   function(query_message, opts, callback)
+    logger.info("vectorcode.query: ", query_message, opts, callback)
     opts = vim.tbl_deep_extend("force", vc_config.get_query_opts(), opts or {})
     if opts.n_query == 0 then
       if opts.notify then
@@ -45,8 +49,10 @@ M.query = vc_config.check_cli_wrap(
       vim.list_extend(args, { "--exclude", vim.api.nvim_buf_get_name(0) })
     end
 
+    logger.debug("vectorcode.query cmd args: ", args)
     local decoded_response = {}
     local job = vim.system(args, { text = true }, function(out)
+      logger.debug("vectorcode.query cmd output: ", out)
       local raw_response
       if out.code == 124 and out.signal == 9 then
         -- killed due to timeout
@@ -77,6 +83,7 @@ M.query = vc_config.check_cli_wrap(
         if type(callback) == "function" then
           callback(decoded_response)
         end
+        logger.info("vectorcode.query result:\n", decoded_response)
       end
     end)
 
@@ -95,6 +102,7 @@ M.vectorise = vc_config.check_cli_wrap(
   ---@param files string|string[] Files to vectorise.
   ---@param project_root string? Add the `--project_root` flag and the passed argument to the command.
   function(files, project_root)
+    logger.info("vectorcode.vectorise: ", files, project_root)
     local args = { "--pipe", "vectorise" }
     if project_root ~= nil then
       vim.list_extend(args, { "--project_root", project_root })
@@ -130,6 +138,7 @@ M.vectorise = vc_config.check_cli_wrap(
         )
       end)
     end
+    logger.debug("vectorcode.vectorise cmd args: ", args)
     require("plenary.job")
       :new({
         command = "vectorcode",
@@ -158,14 +167,17 @@ M.vectorise = vc_config.check_cli_wrap(
 
 ---@param project_root string?
 M.update = vc_config.check_cli_wrap(function(project_root)
+  logger.info("vectorcode.update: ", project_root)
   local args = { "vectorcode", "update" }
   if
     type(project_root) == "string"
     and vim.uv.fs_stat(vim.fs.normalize(project_root)).type == "directory"
   then
     vim.list_extend(args, { "--project_root", project_root })
   end
+  logger.debug("vectorcode.update cmd args: ", args)
   vim.system(args, { stdout = nil, stderr = nil }, function(out)
+    logger.debug("vectorcode.update cmd out:\n", out)
     if get_config().notify then
       vim.schedule(function()
         if out.code == 0 then

lua/vectorcode/jobrunner/cmd.lua

@@ -4,6 +4,7 @@ local runner = {}
 local Job = require("plenary.job")
 ---@type {integer: Job}
 local jobs = {}
+local logger = require("vectorcode.config").logger
 
 function runner.run_async(args, callback, bufnr)
   if type(callback) == "function" then
@@ -14,7 +15,9 @@ function runner.run_async(args, callback, bufnr)
   local cmd = { "vectorcode" }
   args = require("vectorcode.jobrunner").find_root(args, bufnr)
   vim.list_extend(cmd, args)
-
+  logger.debug(
+    ("cmd jobrunner for buffer %s args: %s"):format(bufnr, vim.inspect(args))
+  )
   local job = Job:new({
     command = "vectorcode",
     args = args,
@@ -26,6 +29,7 @@ function runner.run_async(args, callback, bufnr)
         if ok then
           callback(decoded, self:stderr_result())
         else
+          logger.info("cmd runner: failed to decode result:\n", result)
           callback({ result }, self:stderr_result())
         end
       end