feat(logging): vim.log #38906

4 files changed, 310 insertions, 151 deletions

diff --git a/runtime/lua/vim/_core/editor.lua b/runtime/lua/vim/_core/editor.lua
index 412459a7dc..8f8cdf2beb 100644
--- a/runtime/lua/vim/_core/editor.lua
+++ b/runtime/lua/vim/_core/editor.lua
@@ -11,6 +11,7 @@ for k, v in pairs({
   loader = true,
   func = true,
   F = true,
+  log = true,
   lsp = true,
   hl = true,
   diagnostic = true,
@@ -171,19 +172,6 @@ function vim.wait(time, callback, interval, fast_only)
   end
 end
 
---- @nodoc
-vim.log = {
-  --- @enum vim.log.levels
-  levels = {
-    TRACE = 0,
-    DEBUG = 1,
-    INFO = 2,
-    WARN = 3,
-    ERROR = 4,
-    OFF = 5,
-  },
-}
-
 local utfs = {
   ['utf-8'] = true,
   ['utf-16'] = true,
diff --git a/runtime/lua/vim/_meta.lua b/runtime/lua/vim/_meta.lua
index 04de486982..30660ca12c 100644
--- a/runtime/lua/vim/_meta.lua
+++ b/runtime/lua/vim/_meta.lua
@@ -78,6 +78,7 @@ local iter = require('vim.iter')
 vim.iter = iter
 vim.keymap = require('vim.keymap')
 vim.loader = require('vim.loader')
+vim.log = require('vim.log')
 vim.lsp = require('vim.lsp')
 vim.net = require('vim.net')
 vim.pack = require('vim.pack')
diff --git a/runtime/lua/vim/log.lua b/runtime/lua/vim/log.lua
new file mode 100644
index 0000000000..2f98ff683f
--- /dev/null
+++ b/runtime/lua/vim/log.lua
@@ -0,0 +1,279 @@
+--- @brief
+---
+--- The |vim.log| module provides file-backed logger instances.
+---
+--- Use `vim.log.new()` to create a logger, it exposes five writer functions:
+--- `trace()`, `debug()`, `info()`, `warn()`, and `error()`.
+--- They are correspond to log levels defined by |vim.log.levels|.
+---
+--- Example:
+---
+--- ```lua
+--- local log = vim.log.new({ name = 'my-plugin', })
+--- -- By default, logs will be written to {name}.log under `stdpath('log')`.
+---
+--- log.error('request failed', 'timeout')
+--- -- This will write a line like the following to the log file:
+--- --   [ERROR][2024-01-01 12:00:00] source.lua:123    request failed    timeout
+---
+--- -- Set the log level to `INFO`, otherwise the `info()` call below would be ignored,
+--- -- since the default level is `WARN`.
+--- vim.log.set_level(log, vim.log.levels.INFO)
+--- log.info('starting', { buf = vim.api.nvim_get_current_buf() })
+--- -- This will write a line like the following to the log file:
+--- --   [INFO][2024-01-01 12:01:00] source.lua:124    starting    { buf = 1 }
+--- ```
+---
+--- You can also provide a custom formatter function to customize the log output format.
+
+---@class vim.Log
+---
+--- Display name used in notifications emitted by the logger.
+---@field private name string
+---
+--- Minimum level that will be written.
+---@field private current_level integer
+---
+--- Function used to format a log entry.
+---@field private format_func fun(current_level: vim.log.levels, level:vim.log.levels, ...): string?
+---
+--- Path of the log file.
+---@field private filename string
+---
+--- Internal state for the log file handle. `nil` until the file is opened.
+---@field private logfile file*?
+---
+--- Internal state for the log file open error.
+---@field private openerr string?
+---
+--- Writes a message at `vim.log.levels.TRACE`.
+---@field trace fun(...:any): boolean?
+---
+--- Writes a message at `vim.log.levels.DEBUG`.
+---@field debug fun(...:any): boolean?
+---
+--- Writes a message at `vim.log.levels.INFO`.
+---@field info fun(...:any): boolean?
+---
+--- Writes a message at `vim.log.levels.WARN`.
+---@field warn fun(...:any): boolean?
+---
+--- Writes a message at `vim.log.levels.ERROR`.
+---@field error fun(...:any): boolean?
+local M = {}
+
+---@enum vim.log.levels
+---@nodoc
+M.levels = {
+  TRACE = 0,
+  DEBUG = 1,
+  INFO = 2,
+  WARN = 3,
+  ERROR = 4,
+  OFF = 5,
+}
+
+local level_names = {
+  [0] = 'TRACE',
+  [1] = 'DEBUG',
+  [2] = 'INFO',
+  [3] = 'WARN',
+  [4] = 'ERROR',
+  [5] = 'OFF',
+}
+
+local log_date_format = '%F %H:%M:%S'
+
+--- Default formatter used by |vim.log.new()|.
+---
+--- Formats a message as:
+--- `[LEVEL][YYYY-MM-DD HH:MM:SS] source.lua:line<TAB>arg1<TAB>arg2`
+---
+---@param current_level vim.log.levels
+---@param level vim.log.levels
+---@return string?
+local function default_format_func(current_level, level, ...)
+  if level < current_level then
+    return nil
+  end
+
+  -- Stack shape:
+  --   default_format_func <- create_writer closure <- user callsite
+  local info = debug.getinfo(3, 'Sl')
+  local header = string.format(
+    '[%s][%s] %s:%s',
+    level_names[level],
+    os.date(log_date_format),
+    info.short_src,
+    info.currentline
+  )
+  local parts = { header }
+  local argc = select('#', ...)
+  for i = 1, argc do
+    local arg = select(i, ...)
+    table.insert(parts, arg == nil and 'nil' or vim.inspect(arg, { newline = ' ', indent = '' }))
+  end
+  return table.concat(parts, '\t') .. '\n'
+end
+
+---@class vim.log.new.Opts
+---@inlinedoc
+---
+--- Display name used in notifications emitted by the logger.
+---@field name string
+---
+--- Minimum level that will be written.
+--- (default: `vim.log.levels.WARN`)
+---@field current_level? vim.log.levels
+---
+--- Formatter used for each log entry.
+--- Receives the logger's current level, the message level, and the values passed to the writer.
+--- Return a string to write an entry, or `nil` to skip it.
+---@field format_func? fun(current_level: vim.log.levels, level: vim.log.levels, ...): string?
+
+--- Creates a logger instance.
+---
+--- The logger writes formatted messages to a file,
+--- using a per-instance log level and formatting function.
+---
+---@param opts vim.log.new.Opts
+---@return vim.Log
+function M.new(opts)
+  vim.validate('opts', opts, 'table')
+  vim.validate('opts.name', opts.name, 'string')
+  vim.validate('opts.current_level', opts.current_level, 'number', true)
+  vim.validate('opts.format_func', opts.format_func, 'function', true)
+
+  local filename = vim.fs.joinpath(vim.fn.stdpath('log'), opts.name:lower() .. '.log')
+  local log_dir = vim.fs.dirname(filename)
+  if log_dir then
+    -- TODO: Ideally, directory creation should be delayed until open_file(), right before
+    -- opening the log file, but open() can be called from libuv callbacks,
+    -- where using fn.mkdir() is not allowed.
+    vim.fn.mkdir(log_dir, 'p')
+  end
+
+  local log = setmetatable({
+    name = opts.name,
+    filename = filename,
+    current_level = opts.current_level or M.levels.WARN,
+    format_func = opts.format_func or default_format_func,
+  }, { __index = M })
+  log.trace = log:create_writer(M.levels.TRACE)
+  log.debug = log:create_writer(M.levels.DEBUG)
+  log.info = log:create_writer(M.levels.INFO)
+  log.warn = log:create_writer(M.levels.WARN)
+  log.error = log:create_writer(M.levels.ERROR)
+
+  return log
+end
+
+---@param msg string
+---@param level? vim.log.levels
+local function notify(msg, level)
+  if vim.in_fast_event() then
+    vim.schedule(function()
+      vim.notify(msg, level)
+    end)
+  else
+    vim.notify(msg, level)
+  end
+end
+
+--- Opens the log file on first use.
+---
+--- Writes a `[START]` marker when the file is opened successfully.
+---
+---@package
+---@return boolean # `true` if the file is open, `false` on error.
+function M:open_file()
+  if self.logfile then
+    return true
+  end
+  if self.openerr then
+    return false
+  end
+
+  self.logfile, self.openerr = io.open(self.filename, 'a+')
+  if not self.logfile then
+    local err_msg = string.format('Failed to open %s log file: %s', self.name, self.openerr)
+    notify(err_msg, M.levels.ERROR)
+    return false
+  end
+
+  local log_info = vim.uv.fs_stat(self.filename)
+  if log_info and log_info.size > 1e9 then
+    local warn_msg = string.format(
+      '%s log is large (%d MB): %s',
+      self.name,
+      log_info.size / (1000 * 1000),
+      self.filename
+    )
+    notify(warn_msg)
+  end
+
+  -- Start message for logging
+  self.logfile:write(
+    string.format('[START][%s] %s logging initiated\n', os.date(log_date_format), self.name)
+  )
+  return true
+end
+
+--- Creates a writer function for a specific log level.
+---
+---@package
+---@param level vim.log.levels
+---@return fun(...:any): boolean? # Returns `false` if the log file could not be opened.
+function M:create_writer(level)
+  return function(...)
+    local argc = select('#', ...)
+    if argc == 0 then
+      return true
+    end
+    if not self:open_file() then
+      return false
+    end
+    local message = self.format_func(self.current_level, level, ...)
+    if message then
+      assert(self.logfile)
+      self.logfile:write(message)
+      self.logfile:flush()
+    end
+  end
+end
+
+--- Sets the current log level.
+---
+--- Entries below this level are skipped.
+---
+---@param log vim.Log
+---@param level vim.log.levels
+function M.set_level(log, level)
+  vim.validate('level', level, 'number')
+  log.current_level = level
+end
+
+--- Gets the current log level.
+---@param log vim.Log
+---@return vim.log.levels
+function M.get_level(log)
+  return log.current_level
+end
+
+--- Sets the formatter used to produce log entries.
+---
+--- The formatter receives the logger's current level, the message level,
+--- and the values passed to the writer method.
+--- Return a string to write an entry, or `nil` to skip it.
+---
+---@param log vim.Log
+---@param func fun(current_level: vim.log.levels, level: vim.log.levels, ...): string?
+function M.set_format_func(log, func)
+  vim.validate('func', func, function(f)
+    return type(f) == 'function' or f == vim.inspect
+  end, false, 'func must be a function')
+
+  log.format_func = func
+end
+
+return M
diff --git a/runtime/lua/vim/lsp/log.lua b/runtime/lua/vim/lsp/log.lua
index 4bb0ebb830..7786784983 100644
--- a/runtime/lua/vim/lsp/log.lua
+++ b/runtime/lua/vim/lsp/log.lua
@@ -18,7 +18,7 @@
 --- - "ERROR" messages containing "stderr" only indicate that the log was sent to stderr. Many
 ---   servers send harmless messages via stderr.
 
-local log = {}
+local M = {}
 
 local log_levels = vim.log.levels
 
@@ -31,127 +31,26 @@ local protocol = require('vim.lsp.protocol')
 --- Level numbers begin with "TRACE" at 0
 --- @type table<string,integer> | table<integer, string>
 --- @nodoc
-log.levels = vim.deepcopy(log_levels)
+M.levels = vim.deepcopy(log_levels)
 
--- Default log level is warn.
-local current_log_level = log_levels.WARN
-
-local log_date_format = '%F %H:%M:%S'
-
---- Default formatting function.
---- @param level? string
-local function format_func(level, ...)
-  if log_levels[level] < current_log_level then
-    return nil
-  end
-
-  local info = debug.getinfo(2, 'Sl')
-  local header = string.format(
-    '[%s][%s] %s:%s',
-    level,
-    os.date(log_date_format),
-    info.short_src,
-    info.currentline
-  )
-  local parts = { header }
-  local argc = select('#', ...)
-  for i = 1, argc do
-    local arg = select(i, ...)
-    table.insert(parts, arg == nil and 'nil' or vim.inspect(arg, { newline = ' ', indent = '' }))
-  end
-  return table.concat(parts, '\t') .. '\n'
-end
-
-local function notify(msg, level)
-  if vim.in_fast_event() then
-    vim.schedule(function()
-      vim.notify(msg, level)
-    end)
-  else
-    vim.notify(msg, level)
-  end
-end
-
-local logfilename = vim.fs.joinpath(vim.fn.stdpath('log') --[[@as string]], 'lsp.log')
-
--- TODO: Ideally the directory should be created in open_logfile(), right
--- before opening the log file, but open_logfile() can be called from libuv
--- callbacks, where using fn.mkdir() is not allowed.
-vim.fn.mkdir(vim.fn.stdpath('log') --[[@as string]], 'p')
+local log = vim.log.new({
+  name = 'LSP',
+})
 
 --- Returns the log filename.
 ---@return string log filename
-function log.get_filename()
-  return logfilename
-end
-
---- @param s string
-function log._set_filename(s)
-  logfilename = s
-end
-
---- @type file*?, string?
-local logfile, openerr
-
---- Opens log file. Returns true if file is open, false on error
-local function open_logfile()
-  -- Try to open file only once
-  if logfile then
-    return true
-  end
-  if openerr then
-    return false
-  end
-
-  logfile, openerr = io.open(logfilename, 'a+')
-  if not logfile then
-    local err_msg = string.format('Failed to open LSP client log file: %s', openerr)
-    notify(err_msg, log_levels.ERROR)
-    return false
-  end
-
-  local log_info = vim.uv.fs_stat(logfilename)
-  if log_info and log_info.size > 1e9 then
-    local warn_msg = string.format(
-      'LSP client log is large (%d MB): %s',
-      log_info.size / (1000 * 1000),
-      logfilename
-    )
-    notify(warn_msg)
-  end
-
-  -- Start message for logging
-  logfile:write(string.format('[START][%s] LSP logging initiated\n', os.date(log_date_format)))
-  return true
+function M.get_filename()
+  ---@diagnostic disable-next-line: invisible
+  return log.filename
 end
 
 for level, levelnr in pairs(log_levels) do
   -- Also export the log level on the root object.
   ---@diagnostic disable-next-line: no-unknown
-  log[level] = levelnr
+  M[level] = levelnr
 
   -- Add a reverse lookup.
-  log.levels[levelnr] = level
-end
-
---- @param level string
---- @return fun(...:any): boolean?
-local function create_logger(level)
-  return function(...)
-    local argc = select('#', ...)
-    if argc == 0 then
-      return true
-    end
-    if not open_logfile() then
-      return false
-    end
-    local message = format_func(level, ...)
-    if message then
-      assert(logfile)
-      logfile:write(message)
-      logfile:flush()
-    end
-  end
+  M.levels[levelnr] = level
 end
 
 -- If called without arguments, it will check whether the log level is
@@ -159,68 +58,60 @@ end
 -- log at that level (if applicable, it is checked either way).
 
 --- @nodoc
-log.debug = create_logger('DEBUG')
+M.debug = log.debug
 
 --- @nodoc
-log.error = create_logger('ERROR')
+M.error = log.error
 
 --- @nodoc
-log.info = create_logger('INFO')
+M.info = log.info
 
 --- @nodoc
-log.trace = create_logger('TRACE')
+M.trace = log.trace
 
 --- @nodoc
-log.warn = create_logger('WARN')
+M.warn = log.warn
 
 --- Sets the current log level.
 ---@param level (string|integer) One of |vim.log.levels|
-function log.set_level(level)
+function M.set_level(level)
   vim.validate('level', level, { 'string', 'number' })
 
   if type(level) == 'string' then
-    current_log_level =
-      assert(log.levels[level:upper()], string.format('Invalid log level: %q', level))
-  else
-    assert(log.levels[level], string.format('Invalid log level: %d', level))
-    current_log_level = level
-  end
+    level = assert(M.levels[level:upper()], string.format('Invalid log level: %q', level))
+  end ---@cast level vim.log.levels
+  log:set_level(level)
 end
 
 --- Gets the current log level.
 ---@return integer current log level
-function log.get_level()
-  return current_log_level
+function M.get_level()
+  return log:get_level()
 end
 
 --- Sets the formatting function used to format logs. If the formatting function returns nil, the entry won't
 --- be written to the log file.
 ---@param handle fun(level:string, ...): string? Function to apply to log entries. The default will log the level,
 ---date, source and line number of the caller, followed by the arguments.
-function log.set_format_func(handle)
-  vim.validate('handle', handle, function(h)
-    return type(h) == 'function' or h == vim.inspect
-  end, false, 'handle must be a function')
-
-  format_func = handle
+function M.set_format_func(handle)
+  log:set_format_func(function(_, level, ...)
+    return handle(M.levels[level], ...)
+  end)
 end
 
 --- Checks whether the level is sufficient for logging.
 ---@deprecated
 ---@param level integer log level
 ---@return boolean : true if would log, false if not
-function log.should_log(level)
+function M.should_log(level)
   vim.deprecate('vim.lsp.log.should_log', 'vim.lsp.log.set_format_func', '0.13')
-
-  vim.validate('level', level, 'number')
-
-  return level >= current_log_level
+  return level >= vim.log.get_level(log)
 end
 
 --- Convert LSP MessageType to vim.log.levels
 ---
 ---@param message_type lsp.MessageType
-function log._from_lsp_level(message_type)
+function M._from_lsp_level(message_type)
   if message_type == protocol.MessageType.Error then
     return log_levels.ERROR
   elseif message_type == protocol.MessageType.Warning then
@@ -232,4 +123,4 @@ function log._from_lsp_level(message_type)
   end
 end
 
-return log
+return M