File logging (#1053)

* add file logging infrastructure

* log git runner operations

* log configuration and mappings

* document file logging infrastructure

* style fixes

* stylua fixes

* document log file locations

Author: alex-courtis

README.md

@@ -186,7 +186,15 @@ require'nvim-tree'.setup {
         }
       }
     }
-  }
+  },
+  log = {
+    enable = false,
+    types = {
+      all = false,
+      config = false,
+      git = false,
+    },
+  },
 }
 ```
 
@@ -307,6 +315,11 @@ You can toggle the help UI by pressing `g?`.
 3. `toggle` has a second parameter which allows to toggle without focusing the explorer (`require"nvim-tree.toggle(false, false)`).
 4. You can allow nvim-tree to behave like vinegar (see `:help nvim-tree-vinegar`).
 
+## Diagnostic Logging
+
+You may enable diagnostic logging and a file `nvim-tree-HH:MM:SS-username.log` will be created in `$XDG_CACHE_HOME/nvim`, usually `~/.cache/nvim`, containing logs from that nvim session. See `:help nvim-tree.log`.
+
+The files may become large and numerous, so it is advised to turn on logging to diagnose an issue or while reporting a bug, then turn it off.
 
 ## Screenshots
 

doc/nvim-tree-lua.txt

@@ -152,7 +152,15 @@ function.
 	    }
 	  }
         },
-      }
+      },
+      log = {
+	enable = false,
+	types = {
+	  all = false,
+	  config = false,
+	  git = false,
+	},
+      },
     }
 <
 
@@ -451,6 +459,28 @@ Here is a list of the options available in the setup call:
 			`buftype  = { "nofile", "terminal", "help", }`
 		`}`
 
+*nvim-tree.log*
+|log|: configuration for diagnostic logging
+
+  - |log.enable|: enable logging to a file `nvim-tree-HH:MM:SS-username.log`
+    in $XDG_CACHE_HOME/nvim
+      type: `boolean`
+      default: `false`
+
+  - |log.types|: specify which information to log
+
+    - |log.types.all|: everything
+        type: `boolean`
+        default: `false`
+
+    - |log.types.config|: options and mappings, at startup
+        type: `boolean`
+        default: `false`
+
+    - |log.types.git|: git processing
+        type: `boolean`
+        default: `false`
+
 ==============================================================================
 OPTIONS				                  *nvim-tree-options*
 

lua/nvim-tree.lua

@@ -2,6 +2,7 @@ local luv = vim.loop
 local api = vim.api
 
 local lib = require "nvim-tree.lib"
+local log = require "nvim-tree.log"
 local colors = require "nvim-tree.colors"
 local renderer = require "nvim-tree.renderer"
 local view = require "nvim-tree.view"
@@ -390,6 +391,14 @@ local DEFAULT_OPTS = {
       },
     },
   },
+  log = {
+    enable = false,
+    types = {
+      all = false,
+      config = false,
+      git = false,
+    },
+  },
 }
 
 local function merge_options(conf)
@@ -415,6 +424,11 @@ function M.setup(conf)
 
   manage_netrw(opts.disable_netrw, opts.hijack_netrw)
 
+  require("nvim-tree.log").setup(opts)
+
+  log.line("config", "default config + user")
+  log.raw("config", "%s\n", vim.inspect(opts))
+
   require("nvim-tree.actions").setup(opts)
   require("nvim-tree.colors").setup()
   require("nvim-tree.diagnostics").setup(opts)

lua/nvim-tree/actions/init.lua

@@ -1,6 +1,7 @@
 local a = vim.api
 
 local lib = require "nvim-tree.lib"
+local log = require "nvim-tree.log"
 local view = require "nvim-tree.view"
 local util = require "nvim-tree.utils"
 local nvim_tree_callback = require("nvim-tree.config").nvim_tree_callback
@@ -231,6 +232,9 @@ function M.setup(opts)
   else
     M.mappings = merge_mappings(options.list)
   end
+
+  log.line("config", "active mappings")
+  log.raw("config", "%s\n", vim.inspect(M.mappings))
 end
 
 return M

lua/nvim-tree/git/runner.lua

@@ -1,4 +1,5 @@
 local uv = vim.loop
+local log = require "nvim-tree.log"
 local utils = require "nvim-tree.utils"
 
 local Runner = {}
@@ -40,68 +41,88 @@ function Runner:_handle_incoming_data(prev_output, incoming)
   return nil
 end
 
-function Runner:_getopts(stdout_handle)
+function Runner:_getopts(stdout_handle, stderr_handle)
   local untracked = self.list_untracked and "-u" or nil
   local ignored = (self.list_untracked and self.list_ignored) and "--ignored=matching" or "--ignored=no"
   return {
     args = { "--no-optional-locks", "status", "--porcelain=v1", ignored, untracked },
     cwd = self.project_root,
-    stdio = { nil, stdout_handle, nil },
+    stdio = { nil, stdout_handle, stderr_handle },
   }
 end
 
+function Runner:_log_raw_output(output)
+  if output and type(output) == "string" then
+    log.raw("git", "%s", output)
+  end
+end
+
 function Runner:_run_git_job()
   local handle, pid
   local stdout = uv.new_pipe(false)
+  local stderr = uv.new_pipe(false)
   local timer = uv.new_timer()
 
-  local function on_finish()
-    self._done = true
-    if timer:is_closing() or stdout:is_closing() or (handle and handle:is_closing()) then
+  local function on_finish(rc)
+    self.rc = rc or 0
+    if timer:is_closing() or stdout:is_closing() or stderr:is_closing() or (handle and handle:is_closing()) then
       return
     end
     timer:stop()
     timer:close()
     stdout:read_stop()
+    stderr:read_stop()
     stdout:close()
+    stderr:close()
     if handle then
       handle:close()
     end
 
     pcall(uv.kill, pid)
   end
 
+  local opts = self:_getopts(stdout, stderr)
+  log.line("git", "running job with timeout %dms", self.timeout)
+  log.line("git", "git %s", table.concat(opts.args, " "))
+
   handle, pid = uv.spawn(
     "git",
-    self:_getopts(stdout),
-    vim.schedule_wrap(function()
-      on_finish()
+    opts,
+    vim.schedule_wrap(function(rc)
+      on_finish(rc)
     end)
   )
 
   timer:start(
     self.timeout,
     0,
     vim.schedule_wrap(function()
-      on_finish()
+      on_finish(-1)
     end)
   )
 
   local output_leftover = ""
-  local function manage_output(err, data)
+  local function manage_stdout(err, data)
     if err then
       return
     end
+    self:_log_raw_output(data)
     output_leftover = self:_handle_incoming_data(output_leftover, data)
   end
 
-  uv.read_start(stdout, vim.schedule_wrap(manage_output))
+  local function manage_stderr(_, data)
+    self:_log_raw_output(data)
+  end
+
+  uv.read_start(stdout, vim.schedule_wrap(manage_stdout))
+  uv.read_start(stderr, vim.schedule_wrap(manage_stderr))
 end
 
 function Runner:_wait()
-  while not vim.wait(30, function()
-    return self._done
-  end, 30) do
+  local function is_done()
+    return self.rc ~= nil
+  end
+  while not vim.wait(30, is_done) do
   end
 end
 
@@ -113,11 +134,20 @@ function Runner.run(opts)
     list_ignored = opts.list_ignored,
     timeout = opts.timeout or 400,
     output = {},
-    _done = false,
+    rc = nil, -- -1 indicates timeout
   }, Runner)
 
   self:_run_git_job()
   self:_wait()
+
+  if self.rc == -1 then
+    log.line("git", "job timed out")
+  elseif self.rc ~= 0 then
+    log.line("git", "job failed with return code %d", self.rc)
+  else
+    log.line("git", "job success")
+  end
+
   return self.output
 end
 

lua/nvim-tree/log.lua

@@ -0,0 +1,40 @@
+local M = {
+  config = nil,
+  path = nil,
+}
+
+--- Write to log file
+--- @param typ as per log.types config
+--- @param fmt for string.format
+--- @param ... arguments for string.format
+function M.raw(typ, fmt, ...)
+  if not M.path or not M.config.types[typ] and not M.config.types.all then
+    return
+  end
+
+  local line = string.format(fmt, ...)
+  local file = io.open(M.path, "a")
+  io.output(file)
+  io.write(line)
+  io.close(file)
+end
+
+-- Write to log file
+-- time and typ are prefixed and a trailing newline is added
+function M.line(typ, fmt, ...)
+  if not M.path or not M.config.types[typ] and not M.config.types.all then
+    return
+  end
+
+  M.raw(typ, string.format("[%s] [%s] %s\n", os.date "%H:%M:%S", typ, fmt), ...)
+end
+
+function M.setup(opts)
+  M.config = opts.log
+  if M.config and M.config.enable and M.config.types then
+    M.path = string.format("%s/nvim-tree-%s-%s.log", vim.fn.stdpath "cache", os.date "%H:%M:%S", vim.env.USER)
+    print("nvim-tree.lua logging to " .. M.path)
+  end
+end
+
+return M