feat: configure logging, more logging

Most of the new logging is focused on discovery as that seems to be the
largest source of problems.

lua/neotest/adapters/init.lua

@@ -1,3 +1,4 @@
+local logger = require("neotest.logging")
 local config = require("neotest.config")
 local async = require("neotest.async")
 local lib = require("neotest.lib")
@@ -14,6 +15,8 @@ function AdapterGroup:adapters_with_root_dir(cwd)
       table.insert(adapters, { adapter = adapter, root = root })
     end
   end
+  logger.info("Found", #adapters, "adapters for directory", cwd)
+  logger.debug("Adapters:", adapters)
   return adapters
 end
 
@@ -29,6 +32,7 @@ function AdapterGroup:adapters_matching_open_bufs()
   for _, path in ipairs(paths) do
     for _, adapter in ipairs(self:_path_adapters(path)) do
       if adapter.is_test_file(path) and not matched_files[path] then
+        logger.info("Adapter", adapter.name, "matched buffer", path)
         matched_files[path] = true
         table.insert(adapters, adapter)
         break
@@ -41,14 +45,7 @@ end
 function AdapterGroup:adapter_matching_path(path)
   for _, adapter in ipairs(self:_path_adapters(path)) do
     if adapter.is_test_file(path) then
-      return adapter
-    end
-  end
-end
-
-function AdapterGroup:get_file_adapter(file_path)
-  for _, adapter in ipairs(self:_path_adapters(file_path)) do
-    if adapter.is_test_file(file_path) then
+      logger.info("Adapter", adapter.name, "matched path", path)
       return adapter
     end
   end

lua/neotest/client/init.lua

@@ -228,7 +228,7 @@ function NeotestClient:_update_positions(path, args)
   if not adapter then
     return
   end
-  local success, positions = pcall(function()
+  local success, err = pcall(function()
     if lib.files.is_dir(path) then
       -- If existing tree then we have to find the point to merge the trees and update that path rather than trying to
       -- merge an orphan. This happens when a whole new directory is found (e.g. renamed an existing one).
@@ -243,20 +243,25 @@ function NeotestClient:_update_positions(path, args)
           return
         end
       end
+      logger.info("Searching", path, "for test files")
       local files = lib.func_util.filter_list(adapter.is_test_file, lib.files.find(path))
       local positions = lib.files.parse_dir_from_files(path, files)
+      logger.debug("Found", positions)
       self._state:update_positions(adapter_id, positions)
       self:_parse_files(adapter_id, path, files)
     else
+      logger.info("Parsing", path)
       local positions = adapter.discover_positions(path)
-      if positions then
-        self._state:update_positions(adapter_id, positions)
+      if not positions then
+        logger.info("No positions found in", path)
+        return
       end
+      logger.debug("Found", positions)
+      self._state:update_positions(adapter_id, positions)
     end
   end)
-  if not success or not positions then
-    logger.error("Couldn't find positions in path", path, positions)
-    return
+  if not success then
+    logger.error("Couldn't find positions in path", path, err)
   end
 end
 
@@ -271,6 +276,7 @@ function NeotestClient:_parse_files(adapter_id, root, paths)
   for _ = 1, config.projects[root].discovery.concurrent do
     table.insert(workers, worker)
   end
+  logger.info("Discovering files with", #workers, "workers")
   async.util.join(workers)
 end
 

lua/neotest/config/init.lua

@@ -19,7 +19,7 @@ local function define_highlights()
   hi default NeotestMarked ctermfg=Brown guifg=#F79000 gui=bold
   hi default NeotestTarget ctermfg=Red guifg=#F70067
   hi default link NeotestUnknown Normal
-]] )
+]])
 end
 
 local augroup = vim.api.nvim_create_augroup("NeotestColorSchemeRefresh", {})
@@ -33,6 +33,7 @@ define_highlights()
 ---@field default_strategy string|function
 
 ---@class neotest.Config: neotest.CoreConfig
+---@field log_level number Minimum log levels, one of vim.log.levels
 ---@field consumers table<string, neotest.Consumer>
 ---@field icons table<string, string>
 ---@field highlights table<string, string>
@@ -98,6 +99,7 @@ define_highlights()
 ---@private
 ---@type neotest.Config
 local default_config = {
+  log_level = vim.log.levels.WARN,
   adapters = {},
   discovery = {
     enabled = true,
@@ -216,6 +218,7 @@ end
 ---@param config neotest.Config
 ---@private
 function NeotestConfigModule.setup(config)
+  ---@type neotest.Config
   user_config = vim.tbl_deep_extend("force", default_config, config)
   --- Avoid mutating default for docgen
   user_config.discovery = vim.tbl_deep_extend(
@@ -232,6 +235,11 @@ function NeotestConfigModule.setup(config)
   for project_root, project_config in pairs(config.projects or {}) do
     NeotestConfigModule.setup_project(project_root, project_config)
   end
+
+  local logger = require("neotest.logging")
+  logger:set_level(user_config.log_level)
+  logger.info("Configuration complete")
+  logger.debug("User config", user_config)
 end
 
 function NeotestConfigModule.setup_project(project_root, config)
@@ -243,7 +251,10 @@ function NeotestConfigModule.setup_project(project_root, config)
     running = user_config.running,
   })
   user_config.projects[path].discovery.concurrent =
-  convert_concurrent(user_config.projects[path].discovery.concurrent)
+    convert_concurrent(user_config.projects[path].discovery.concurrent)
+  local logger = require("neotest.logging")
+  logger.info("Project", path, "configuration complete")
+  logger.debug("Project config", user_config.projects[path])
 end
 
 function NeotestConfigModule._format_default()

lua/neotest/lib/file/init.lua

@@ -1,3 +1,4 @@
+local logger = require("neotest.logging")
 local Path = require("plenary.path")
 local async = require("neotest.async")
 local filetype = require("plenary.filetype")
@@ -10,6 +11,7 @@ local M = {}
 ---@param file_path string
 ---@return string
 function M.read(file_path)
+  logger.debug("Reading file: " .. file_path)
   local open_err, file_fd = async.uv.fs_open(file_path, "r", 438)
   assert(not open_err, open_err)
   local stat_err, stat = async.uv.fs_fstat(file_fd)
@@ -21,6 +23,16 @@ function M.read(file_path)
   return data
 end
 
+function M.write(file_path, data)
+  logger.debug("Writing file: " .. file_path)
+  local open_err, file_fd = async.uv.fs_open(file_path, "w", 438)
+  assert(not open_err, open_err)
+  local write_err = async.uv.fs_write(file_fd, data, 0)
+  assert(not write_err, write_err)
+  local close_err = async.uv.fs_close(file_fd)
+  assert(not close_err, close_err)
+end
+
 ---@async
 function M.read_lines(file_path)
   local data = M.read(file_path)
@@ -142,16 +154,19 @@ function M.parent(path)
 end
 
 M.sep = (function()
+  local res
   if jit then
     local os = string.lower(jit.os)
     if os == "linux" or os == "osx" or os == "bsd" then
-      return "/"
+      res = "/"
     else
-      return "\\"
+      res = "\\"
     end
   else
-    return package.config:sub(1, 1)
+    res = package.config:sub(1, 1)
   end
+  logger.debug("Path separator:", res)
+  return res
 end)()
 
 ---@type fun(path: string): string

lua/neotest/logging.lua

@@ -1,16 +1,6 @@
--- Adapted from nvim-dap log.lua
-
-local M = {}
+local config = require("neotest.config")
 local loggers = {}
 
-M.levels = {
-  TRACE = 0,
-  DEBUG = 1,
-  INFO = 2,
-  WARN = 3,
-  ERROR = 4,
-}
-
 local log_date_format = "%FT%H:%M:%SZ%z"
 
 ---@class neotest.Logger
@@ -19,7 +9,6 @@ local log_date_format = "%FT%H:%M:%SZ%z"
 ---@field info function
 ---@field warn function
 ---@field error function
-
 local Logger = {}
 
 ---@return neotest.Logger
@@ -32,11 +21,24 @@ function Logger.new(filename, opts)
   logger = {}
   setmetatable(logger, { __index = Logger })
   loggers[filename] = logger
-  local path_sep = vim.loop.os_uname().sysname == "Windows" and "\\" or "/"
+  local path_sep = (function()
+    if jit then
+      local os = string.lower(jit.os)
+      if os == "linux" or os == "osx" or os == "bsd" then
+        return "/"
+      else
+        return "\\"
+      end
+    else
+      return package.config:sub(1, 1)
+    end
+  end)()
+
   local function path_join(...)
     return table.concat(vim.tbl_flatten({ ... }), path_sep)
   end
-  logger._level = opts.level or M.levels.DEBUG
+
+  logger._level = opts.level or config.log_level
   local ok, logpath = pcall(vim.fn.stdpath, "log")
   if not ok then
     logpath = vim.fn.stdpath("cache")
@@ -45,7 +47,7 @@ function Logger.new(filename, opts)
 
   vim.fn.mkdir(logpath, "p")
   local logfile = assert(io.open(logger._filename, "a+"))
-  for level, levelnr in pairs(M.levels) do
+  for level, levelnr in pairs(vim.log.levels) do
     logger[level:lower()] = function(...)
       local argc = select("#", ...)
       if levelnr < logger._level then
@@ -62,9 +64,11 @@ function Logger.new(filename, opts)
       for i = 1, argc do
         local arg = select(i, ...)
         if arg == nil then
-          table.insert(parts, "nil")
+          table.insert(parts, "<nil>")
         elseif type(arg) == "string" then
           table.insert(parts, arg)
+        elseif type(arg) == "table" and arg.__tostring then
+          table.insert(parts, arg.__tostring(arg))
         else
           table.insert(parts, vim.inspect(arg))
         end
@@ -79,7 +83,7 @@ end
 
 function Logger:set_level(level)
   self._level = assert(
-    M.levels[tostring(level):upper()],
+    type(level) == "number" and level or vim.log.levels[tostring(level):upper()],
     string.format("Log level must be one of (trace, debug, info, warn, error), got: %q", level)
   )
 end

lua/neotest/types/tree.lua

@@ -37,6 +37,10 @@ function Tree.from_list(data, key)
   return x
 end
 
+function Tree:__tostring()
+  return vim.inspect(self:to_list())
+end
+
 function Tree:to_list()
   if #self._children == 0 then
     return { self._data }