feat: improve context for logging

- add more watcher logging

Author: lewis6991

lua/gitsigns/actions/blame.lua

@@ -332,7 +332,6 @@ end
 --- @async
 --- @param opts Gitsigns.BlameOpts?
 function M.blame(opts)
-  local __FUNC__ = 'blame'
   local bufnr = api.nvim_get_current_buf()
   local win = api.nvim_get_current_win()
   local bcache = cache[bufnr]

lua/gitsigns/actions/diffthis.lua

@@ -213,8 +213,6 @@ end
 --- @param relpath string?
 --- @return boolean did_attach
 function M.show(bufnr, base, relpath)
-  local __FUNC__ = 'show'
-
   bufnr = bufnr or api.nvim_get_current_buf()
 
   if not cache[bufnr] then

lua/gitsigns/attach.lua

@@ -67,7 +67,6 @@ end
 --- @param _ 'reload'
 --- @param bufnr integer
 local function on_reload(_, bufnr)
-  local __FUNC__ = 'on_reload'
   assert(cache[bufnr]):invalidate()
   dprint('Reload')
   manager.update_sync_debounced(bufnr)
@@ -360,8 +359,8 @@ M.attach = throttle_async({ hash = 1 }, function(cbuf, ctx, aucmd)
 
   cache[cbuf] = Cache.new(cbuf, file, git_obj)
 
-  if config.watch_gitdir.enable then
-    dprintf('Watching git dir')
+  if git_obj.repo:has_watcher() then
+    dprintf('Watching git dir %s', git_obj.repo.gitdir)
 
     --- Throttle to:
     --- - ensure handler is only triggered once per git operation.

lua/gitsigns/cli.lua

@@ -59,7 +59,6 @@ end
 --- @async
 --- @param params vim.api.keyset.create_user_command.command_args
 function M.run(params)
-  local __FUNC__ = 'cli.run'
   local pos_args_raw, named_args_raw = argparse.parse_args(params.args)
 
   local func = pos_args_raw[1]

lua/gitsigns/debug/log.lua

@@ -59,31 +59,128 @@ local function getvarvalue(name, lvl)
   return getfenv(func)[name]
 end
 
+--- @param info debuglib.DebugInfo
+--- @return string
+local function get_cur_module(info)
+  local src = info.source or '???'
+
+  if vim.startswith(src, '@') then
+    src = src:sub(2)
+  end
+  src = src:gsub('^%./', '')
+
+  local rel = src:match('^lua/(.+)$') or src:match('[/\\]lua[/\\](.+)$')
+  local module = (rel or src):gsub('%.lua$', ''):gsub('/init$', ''):gsub('[\\/]', '.')
+  return module
+end
+
+--- @param tbl table
+--- @param func function
+--- @return string?
+local function find_func_name(tbl, func)
+  for k, v in pairs(tbl) do
+    if v == func and type(k) == 'string' then
+      return k
+    end
+  end
+end
+
+--- @param func function?
 --- @param lvl integer
---- @return {name:string, bufnr: integer}
-local function get_context(lvl)
+--- @return string?
+local function get_cur_func_name_from_self(func, lvl)
+  if not func then
+    return
+  end
+
+  local self_tbl = getvarvalue('self', lvl)
+  if type(self_tbl) ~= 'table' then
+    return
+  end
+
+  local name = find_func_name(self_tbl, func)
+  if name then
+    return name
+  end
+
+  local mt = getmetatable(self_tbl)
+  local idx = mt and mt.__index
+  if type(idx) ~= 'table' then
+    return
+  end
+
+  local name1 = find_func_name(idx, func)
+  if name1 then
+    return name1
+  end
+end
+
+--- @param func function?
+--- @param module string?
+--- @return string?
+local function get_cur_func_name_from_loaded(func, module)
+  if not func then
+    return
+  end
+  local tbl = package.loaded[module]
+  if type(tbl) == 'table' then
+    return find_func_name(tbl, func)
+  end
+end
+
+local func_names_cache = {} --- @type table<function, string>
+
+--- @param info debuglib.DebugInfo
+--- @param lvl integer
+--- @param module string?
+--- @return string
+local function get_cur_func_name(info, lvl, module)
   lvl = lvl + 1
 
-  local name = getvarvalue('__FUNC__', lvl)
-  if not name then
-    local name0 = debug.getinfo(lvl, 'n').name or ''
-    name = name0:gsub('(.*)%d+$', '%1')
+  local func = info.func
+
+  if func_names_cache[func] then
+    return func_names_cache[func]
   end
 
+  local name = getvarvalue('__FUNC__', lvl) --[[@as string?]]
+    or info.name
+    or get_cur_func_name_from_self(func, lvl)
+    or get_cur_func_name_from_loaded(func, module)
+    or (info.what == 'main') and 'main'
+    or ('<anonymous@%d>'):format(info.linedefined or 0)
+
+  func_names_cache[func] = name
+
+  return name
+end
+
+--- @param lvl integer
+--- @return {module: string?, name:string, bufnr: integer}
+local function get_context(lvl)
+  lvl = lvl + 1
+  local info = debug.getinfo(lvl, 'nSf') or {} --- @type any
+  local module = get_cur_module(info)
+  local func = get_cur_func_name(info, lvl, module)
+
+  module = module:gsub('^gitsigns%.', '')
+
+  func = func:gsub('(.*)%d+$', '%1')
+
   local bufnr = getvarvalue('bufnr', lvl)
     or getvarvalue('_bufnr', lvl)
     or getvarvalue('cbuf', lvl)
     or getvarvalue('buf', lvl)
 
-  return { name = name, bufnr = bufnr }
+  return { module = module, name = func, bufnr = bufnr }
 end
 
 local function tostring(obj)
   return type(obj) == 'string' and obj or vim.inspect(obj)
 end
 
--- If called in a callback then make sure the callback defines a __FUNC__
--- variable which can be used to identify the name of the function.
+--- If called in a callback then make sure the callback defines a __FUNC__
+--- variable which can be used to identify the name of the function.
 --- @param kind string
 --- @param lvl integer
 --- @param ... any
@@ -96,7 +193,7 @@ local function cprint(kind, lvl, ...)
   local msg = table.concat(msgs, ' ')
   local ctx = get_context(lvl)
   local time = (uv.hrtime() - start_time) / 1e6
-  local ctx1 = ctx.name
+  local ctx1 = ctx.module and ctx.module .. '.' .. ctx.name or ctx.name
   if ctx.bufnr then
     ctx1 = string.format('%s(%s)', ctx1, ctx.bufnr)
   end

lua/gitsigns/git/repo.lua

@@ -1,5 +1,6 @@
 local async = require('gitsigns.async')
 local git_command = require('gitsigns.git.cmd')
+local config = require('gitsigns.config').config
 local log = require('gitsigns.debug.log')
 local util = require('gitsigns.util')
 local errors = require('gitsigns.git.errors')
@@ -20,7 +21,7 @@ local uv = vim.uv or vim.loop ---@diagnostic disable-line: deprecated
 --- Username configured for the repo.
 --- Needed for to determine "You" in current line blame.
 --- @field username string
---- @field private _watcher Gitsigns.Repo.Watcher
+--- @field private _watcher? Gitsigns.Repo.Watcher
 local M = {}
 
 --- @param gitdir string
@@ -74,6 +75,7 @@ end
 --- @param callback fun() Callback function to be invoked on update.
 --- @return fun() deregister Function to remove the callback from the watcher.
 function M:on_update(callback)
+  assert(self._watcher, 'Watcher not initialized')
   return self._watcher:on_update(callback)
 end
 
@@ -162,15 +164,21 @@ function M._new(info)
   --- @type Gitsigns.Repo
   local self = setmetatable(info, { __index = M })
   self.username = self:command({ 'config', 'user.name' }, { ignore_error = true })[1]
-  self._watcher = Watcher.new(self.gitdir)
-  self._watcher:on_head_update(function()
-    self.abbrev_head = abbrev_head(self.gitdir)
-    log.dprintf('HEAD changed, updating abbrev_head to %s', self.abbrev_head)
-  end)
+  if config.watch_gitdir.enable then
+    self._watcher = Watcher.new(self.gitdir)
+    self._watcher:on_head_update(function()
+      self.abbrev_head = abbrev_head(self.gitdir)
+      log.dprintf('HEAD changed, updating abbrev_head to %s', self.abbrev_head)
+    end)
+  end
 
   return self
 end
 
+function M:has_watcher()
+  return self._watcher ~= nil
+end
+
 local sem = async.semaphore(1)
 
 --- @async

lua/gitsigns/git/repo/watcher.lua

@@ -44,6 +44,7 @@ function Watcher.new(gitdir)
     handle:close()
   end)
 
+  log.dprintf('Starting git dir watcher on %s', gitdir)
   self.handle:start(gitdir, {}, Watcher.handler1(util.weak_ref(self)))
 
   return self
@@ -66,8 +67,6 @@ end
 --- @private
 --- @param weak_self {ref:Gitsigns.Repo.Watcher}
 function Watcher.handler2(weak_self)
-  local __FUNC__ = 'watcher (debounced)'
-
   local self = weak_self.ref
   if not self then
     return -- garbage collected
@@ -93,11 +92,12 @@ function Watcher.handler1(weak_self)
   --- @param filename string
   --- @param events { change: boolean?, rename: boolean? }
   return function(err, filename, events)
-    local __FUNC__ = 'watcher_cb'
+    local __FUNC__ = 'watcher.handler1'
 
     local watcher = weak_self.ref
     if not watcher then
-      return -- garbage collected
+      log.dprint('watcher was garbage collected')
+      return
     end
 
     if err then

lua/gitsigns/signs.lua

@@ -152,7 +152,6 @@ end
 --- @param staged? boolean
 --- @return Gitsigns.Signs
 function M.new(staged)
-  local __FUNC__ = 'signs.init'
   local self = setmetatable({}, { __index = M })
   self.config = staged and config.signs_staged or config.signs
   Config.subscribe(staged and 'signs_staged' or 'signs', function()

lua/gitsigns/system.lua

@@ -10,7 +10,6 @@ local system = vim.fn.has('nvim-0.11.2') == 1 and vim.system or require('gitsign
 --- @param on_exit fun(obj: vim.SystemCompleted)
 --- @return vim.SystemObj
 function M.system(cmd, opts, on_exit)
-  local __FUNC__ = 'run_job'
   log.dprint(unpack(cmd))
   return system(cmd, opts, on_exit)
 end

test/gitdir_watcher_spec.lua

@@ -41,18 +41,18 @@ describe('gitdir_watcher', function()
     command('Gitsigns clear_debug')
     edit(test_file)
 
-    local revparse_pat = ('run_job: git .* rev-parse --show-toplevel --absolute-git-dir --abbrev-ref HEAD'):gsub(
+    local revparse_pat = ('system.system: git .* rev-parse --show-toplevel --absolute-git-dir --abbrev-ref HEAD'):gsub(
       '%-',
       '%%-'
     )
 
     match_debug_messages({
-      'attach(1): Attaching (trigger=BufReadPost)',
+      'attach.attach(1): Attaching (trigger=BufReadPost)',
       np(revparse_pat),
-      np('run_job: git .* config user.name'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file)),
-      n('attach(1): Watching git dir'),
-      np('run_job: git .* show .*'),
+      np('system.system: git .* config user.name'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file)),
+      np('attach%.attach%(1%): Watching git dir .*'),
+      np('system.system: git .* show .*'),
     })
 
     eq({ [1] = test_file }, get_bufs())
@@ -63,13 +63,13 @@ describe('gitdir_watcher', function()
     git('mv', test_file, test_file2)
 
     match_debug_messages({
-      p('watcher_cb: Git dir update: .*'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file)),
-      np('run_job: git .* diff %-%-name%-status .* %-%-cached'),
-      n('handle_moved(1): File moved to dummy.txt2'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file2)),
-      np('handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt to .*/dummy.txt2'),
-      np('run_job: git .* show .*'),
+      p('git.repo.watcher.watcher.handler: Git dir update: .*'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file)),
+      np('system.system: git .* diff %-%-name%-status .* %-%-cached'),
+      n('attach.handle_moved(1): File moved to dummy.txt2'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file2)),
+      np('attach%.handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt to .*/dummy.txt2'),
+      np('system.system: git .* show .*'),
     })
 
     eq({ [1] = test_file2 }, get_bufs())
@@ -81,13 +81,13 @@ describe('gitdir_watcher', function()
     git('mv', test_file2, test_file3)
 
     match_debug_messages({
-      p('watcher_cb: Git dir update: .*'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file2)),
-      np('run_job: git .* diff %-%-name%-status .* %-%-cached'),
-      n('handle_moved(1): File moved to dummy.txt3'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file3)),
-      np('handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt2 to .*/dummy.txt3'),
-      np('run_job: git .* show .*'),
+      p('git.repo.watcher.watcher.handler: Git dir update: .*'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file2)),
+      np('system.system: git .* diff %-%-name%-status .* %-%-cached'),
+      n('attach.handle_moved(1): File moved to dummy.txt3'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file3)),
+      np('attach%.handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt2 to .*/dummy.txt3'),
+      np('system.system: git .* show .*'),
     })
 
     eq({ [1] = test_file3 }, get_bufs())
@@ -97,14 +97,14 @@ describe('gitdir_watcher', function()
     git('mv', test_file3, test_file)
 
     match_debug_messages({
-      p('watcher_cb: Git dir update: .*'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file3)),
-      np('run_job: git .* diff %-%-name%-status .* %-%-cached'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file)),
-      n('handle_moved(1): Moved file reset'),
-      np('run_job: git .* ls%-files .* ' .. vim.pesc(test_file)),
-      np('handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt3 to .*/dummy.txt'),
-      np('run_job: git .* show .*'),
+      p('git.repo.watcher.watcher.handler: Git dir update: .*'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file3)),
+      np('system.system: git .* diff %-%-name%-status .* %-%-cached'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file)),
+      n('attach.handle_moved(1): Moved file reset'),
+      np('system.system: git .* ls%-files .* ' .. vim.pesc(test_file)),
+      np('attach%.handle_moved%(1%): Renamed buffer 1 from .*/dummy.txt3 to .*/dummy.txt'),
+      np('system.system: git .* show .*'),
     })
 
     eq({ [1] = test_file }, get_bufs())