fix: improve logging

Author: smjonas

README.md

@@ -88,7 +88,6 @@ require("live-command").setup {
       change = "DiffChange",
     },
   },
-  debug = false,
 }
 ```
 
@@ -123,15 +122,6 @@ deletion edits will not be undone which is otherwise done to make the text chang
 
 ---
 
-`debug: boolean`
-
-Default: `false`
-
-If `true`, more stuff (not only errors) will be logged. After previewing a command,
-you can view the log by running `:LiveCommandLog`.
-
----
-
 Like this project? Give it a :star: to show your support!
 
 Also consider checking out my other plugin [inc-rename.nvim](https://github.com/smjonas/inc-rename.nvim),

lua/live-command/init.lua

@@ -11,6 +11,10 @@ M.defaults = {
 }
 
 local api = vim.api
+
+---@type Logger
+local logger
+
 ---@class Remote
 local remote
 
@@ -22,18 +26,6 @@ local should_cache_lines = true
 local cached_lines
 local prev_lazyredraw
 
-local logs = {}
-local function log(msg, level)
-  level = level or "TRACE"
-  if M.debug or level ~= "TRACE" then
-    msg = type(msg) == "function" and msg() or msg
-    logs[level] = logs[level] or {}
-    for _, line in ipairs(vim.split(msg .. "\n", "\n")) do
-      table.insert(logs[level], line)
-    end
-  end
-end
-
 -- Inserts str_2 into str_1 at the given position.
 local function string_insert(str_1, str_2, pos)
   return str_1:sub(1, pos - 1) .. str_2 .. str_1:sub(pos)
@@ -55,7 +47,7 @@ local function add_inline_highlights(line, cached_lns, updated_lines, undo_delet
   local line_a = splice(cached_lns[line])
   local line_b = splice(updated_lines[line])
   local line_diff = vim.diff(line_a, line_b, { result_type = "indices" })
-  log(function()
+  logger.trace(function()
     return ("Changed lines (line %d):\nOriginal: '%s' (len=%d)\nUpdated:  '%s' (len=%d)\n\nInline hunks: %s"):format(
       line,
       cached_lns[line],
@@ -113,10 +105,10 @@ local function get_diff_highlights(cached_lns, updated_lines, line_range, opts)
   local hunks = vim.diff(table.concat(cached_lns, "\n"), table.concat(updated_lines, "\n"), {
     result_type = "indices",
   })
-  log(("Visible line range: %d-%d"):format(line_range[1], line_range[2]))
+  logger.trace(("Visible line range: %d-%d"):format(line_range[1], line_range[2]))
 
   for i, hunk in ipairs(hunks) do
-    log(function()
+    logger.trace(function()
       return ("Hunk %d/%d: %s"):format(i, #hunks, vim.inspect(hunk))
     end)
 
@@ -132,7 +124,7 @@ local function get_diff_highlights(cached_lns, updated_lines, line_range, opts)
         end_line = start_line + (count_a - count_b) - 1
       end
 
-      log(function()
+      logger.trace(function()
         return ("Lines %d-%d:\nOriginal: %s\nUpdated: %s"):format(
           start_line,
           end_line,
@@ -187,10 +179,15 @@ M._preview_across_lines = get_diff_highlights
 
 ---@param cmd string
 local function run_cmd(cmd)
+  if not chan_id then
+    logger.trace("run_cmd: skipped as chan_id is not set")
+    return
+  end
+
   local cursor_pos = api.nvim_win_get_cursor(0)
   cursor_row, cursor_col = cursor_pos[1], cursor_pos[2]
 
-  log(function()
+  logger.trace(function()
     return ("Previewing command: %s (l=%d,c=%d)"):format(cmd, cursor_row, cursor_col)
   end)
   return remote.run_cmd(chan_id, cmd, cursor_row, cursor_col)
@@ -201,7 +198,6 @@ local function command_preview(opts, preview_ns, preview_buf)
   -- Any errors that occur in the preview function are not directly shown to the user but stored in vim.v.errmsg.
   -- Related: https://github.com/neovim/neovim/issues/18910.
   vim.v.errmsg = ""
-  logs = {}
   local args = opts.cmd_args
   local command = opts.command
 
@@ -244,7 +240,7 @@ local function command_preview(opts, preview_ns, preview_buf)
     set_lines(updated_lines)
     -- This should not happen
     if not opts.line1 then
-      log("No line1 range provided", "ERROR")
+      logger.error("No line1 range provided")
     end
     return 2
   end
@@ -258,7 +254,7 @@ local function command_preview(opts, preview_ns, preview_buf)
     undo_deletions = command.hl_groups["deletion"] ~= false,
     inline_highlighting = command.inline_highlighting,
   })
-  log(function()
+  logger.trace(function()
     return "Highlights: " .. vim.inspect(highlights)
   end)
 
@@ -283,12 +279,12 @@ local function restore_buffer_state()
   vim.o.lazyredraw = prev_lazyredraw
   should_cache_lines = true
   if vim.v.errmsg ~= "" then
-    log(("An error occurred in the preview function:\n%s"):format(vim.inspect(vim.v.errmsg)), "ERROR")
+    logger.error(("An error occurred in the preview function:\n%s"):format(vim.inspect(vim.v.errmsg)))
   end
 end
 
 local function execute_command(command)
-  log("Executing command: " .. command)
+  logger.trace("Executing command: " .. command)
   vim.cmd(command)
   restore_buffer_state()
 end
@@ -408,22 +404,18 @@ M.setup = function(user_config)
   local config = vim.tbl_deep_extend("force", M.defaults, user_config or {})
   validate_config(config)
   create_user_commands(config.commands)
+  logger = require("live-command.logger")
   remote = require("live-command.remote")
 
-  remote.init_rpc(function(id)
+  remote.init_rpc(logger, function(id)
     chan_id = id
   end)
   create_autocmds()
+end
 
-  M.debug = user_config.debug
-
-  api.nvim_create_user_command("LiveCommandLog", function()
-    local msg = ("live-command log\n================\n\n%s%s"):format(
-      logs.ERROR and "[ERROR]\n" .. table.concat(logs.ERROR, "\n") .. (logs.TRACE and "\n" or "") or "",
-      logs.TRACE and "[TRACE]\n" .. table.concat(logs.TRACE, "\n") or ""
-    )
-    vim.notify(msg)
-  end, { nargs = 0 })
+---@param logger_ Logger
+M._set_logger = function(logger_)
+  logger = logger_
 end
 
 M.version = "1.3.0"

lua/live-command/logger.lua

@@ -0,0 +1,36 @@
+---@class Logger
+local M = {}
+
+---@type Log[]
+local logs = {}
+
+---@class Log
+---@field msg string
+---@field level number
+
+---@param msg string|fun():string
+M.trace = function(msg)
+  msg = type(msg) == "function" and msg() or msg
+  table.insert(logs, { msg = msg, level = vim.log.levels.TRACE })
+end
+
+M.error = function(msg)
+  msg = type(msg) == "function" and msg() or msg
+  table.insert(logs, { msg = msg, level = vim.log.levels.ERROR })
+end
+
+vim.api.nvim_create_user_command("LiveCommandLog", function()
+  local msgs = {}
+  for i, log in ipairs(logs) do
+    local level = ""
+    if log.level == vim.log.levels.TRACE then
+      level = "[TRACE] "
+    elseif log.level == vim.log.levels.ERROR then
+      level = "[ERROR] "
+    end
+    msgs[i] = level .. log.msg
+  end
+  vim.notify(table.concat(msgs, "\n"))
+end, { nargs = 0 })
+
+return M

lua/live-command/remote.lua

@@ -1,14 +1,17 @@
 ---@class Remote
 local M = {}
 
-local tmp_file = os.tmpname()
+---@type Logger
+local logger
+
 local uv = vim.loop
+local tmp_file = os.tmpname()
 local dirty = true
 
 ---@type number
 local reference_time
 
-local REFERENCE_TIME_OFFSET = 1
+local REFERENCE_TIME_OFFSET = -1
 
 ---@param server_address string
 ---@param on_chan_id fun(chan_id:number)
@@ -31,17 +34,22 @@ local try_connect = function(server_address, on_chan_id, num_retries)
 end
 
 --- Starts a new Nvim instance and connects to it via RPC.
+---@param logger_ Logger
 ---@param on_chan_id fun(chan_id: number)
-M.init_rpc = function(on_chan_id)
+M.init_rpc = function(logger_, on_chan_id)
+  logger = logger_
   local basename = vim.fs.normalize(vim.fn.stdpath("cache"))
   local server_address = basename .. "/live_command_server.pipe"
 
   -- Try to connect to an existing server that has already been spawned
   local success = try_connect(server_address, on_chan_id, 1)
   if success then
+    logger.trace(("init_rpc: connected to existing server"):format(reference_time))
     return
   end
 
+  logger.trace("init_rpc: spawning new server")
+
   -- Use environment variables from parent process
   local env = { "LIVECOMMAND_NVIM_SERVER=1" }
   for k, v in pairs(uv.os_environ()) do
@@ -60,40 +68,41 @@ M.init_rpc = function(on_chan_id)
       handle:close()
     end)
   )
+
   assert(handle)
   success = try_connect(server_address, on_chan_id, 100)
-  if not success then
+  if success then
+    logger.trace("init_rpc: connected to server")
+  else
     vim.notify("[live-command.nvim] failed to connect to remote Neovim instance after 1000 ms", vim.log.levels.ERROR)
   end
 end
 
--- The global dirty flag indicates that other spawned Nvim instances need to reload the
--- temp file. The flag is encoded by increasing the modified time of the temp file.
-local set_global_dirty_flag = function()
+---@return boolean
+local check_global_dirty_flag = function()
   local stat = uv.fs_stat(tmp_file)
-  uv.fs_utime(tmp_file, stat.atime.nsec, reference_time + REFERENCE_TIME_OFFSET)
-  local new_stat = uv.fs_stat(tmp_file)
-  assert(new_stat.atime.nsec == stat.atime.nsec)
+  local is_dirty = stat.mtime.sec == reference_time + REFERENCE_TIME_OFFSET
+  logger.trace("check_global_dirty_flag: " .. tostring(is_dirty))
+  return is_dirty
 end
 
----@return boolean
-local check_global_dirty_flag = function()
+-- The global dirty flag indicates that other spawned Nvim instances need to reload the
+-- temp file. The flag is encoded by decreasing the modified time of the temp file by 1.
+local set_global_dirty_flag = function(is_set)
   local stat = uv.fs_stat(tmp_file)
-  local x = stat.mtime.sec == reference_time + REFERENCE_TIME_OFFSET
-  if x then
-    print("DIRRY")
-  end
-  return x
+  local mtime = is_set and reference_time + REFERENCE_TIME_OFFSET or reference_time
+  uv.fs_utime(tmp_file, stat.atime.sec, mtime)
+  logger.trace("set_global_dirty_flag: " .. tostring(is_set))
 end
 
-M.on_buffer_updated = function()
+M.on_buffer_updated = function(e)
   dirty = true
 end
 
 M.on_buffer_saved = function()
   -- Writing a buffer to disk sets the global dirty flag
   if dirty then
-    set_global_dirty_flag()
+    set_global_dirty_flag(true)
   end
 end
 
@@ -104,9 +113,13 @@ M.sync = function(chan_id)
     return
   end
 
-  dirty = dirty or check_global_dirty_flag()
+  local checked_global_dirty_flag = false
+  if not dirty then
+    dirty = check_global_dirty_flag()
+    checked_global_dirty_flag = true
+  end
+
   if dirty then
-    print("dirty")
     -- Synchronize buffers by writing out the current buffer contents to a temporary file.
     -- Remove A and F option values to not affect the alternate file and the buffer name.
     vim.cmd("let c=&cpoptions | set cpoptions-=A | set cpoptions-=F | silent w! " .. tmp_file .. " | let &cpoptions=c")
@@ -118,6 +131,9 @@ M.sync = function(chan_id)
       false
     )
     dirty = false
+    if checked_global_dirty_flag then
+      set_global_dirty_flag(false)
+    end
   end
 end
 

tests/init_spec.lua

@@ -1,6 +1,10 @@
 local live_command = require("live-command")
 
 describe("inline_highlights", function()
+  setup(function()
+    live_command._set_logger(require("live-command.logger"))
+  end)
+
   -- Checks for the case when the end of the line was unchanged
   it("single insertion", function()
     local highlights = {}
@@ -56,7 +60,7 @@ describe("inline_highlights", function()
       { kind = "change", line = 1, column = 1, length = 4 },
       { kind = "change", line = 1, column = 8, length = 1 },
     }, highlights)
-    assert.are_same({"test = Function()"}, updated_lines)
+    assert.are_same({ "test = Function()" }, updated_lines)
   end)
 
   it("change should not use negative column values", function()
@@ -81,7 +85,7 @@ describe("inline_highlights", function()
       { kind = "deletion", line = 1, column = 3, length = 2 },
       { kind = "deletion", line = 1, column = 6, length = 19 },
     }, highlights)
-    assert.are_same({"le plugins.nvim-surround"}, updated_lines)
+    assert.are_same({ "le plugins.nvim-surround" }, updated_lines)
   end)
 
   it("deletion", function()