refactor(lsp): tidy up logging

runtime/lua/vim/lsp.lua

@@ -798,9 +798,7 @@ function lsp.start_client(config)
   ---@param method (string) LSP method name
   ---@param params (table) The parameters for that method.
   function dispatch.notification(method, params)
-    if log.trace() then
+    log.trace('notification', method, params)
-      log.trace('notification', method, params)
-    end
     local handler = resolve_handler(method)
     if handler then
       -- Method name is provided here for convenience.
@@ -816,19 +814,13 @@ function lsp.start_client(config)
   ---@return any result
   ---@return lsp.ResponseError error code and message set in case an exception happens during the request.
   function dispatch.server_request(method, params)
-    if log.trace() then
+    log.trace('server_request', method, params)
-      log.trace('server_request', method, params)
-    end
     local handler = resolve_handler(method)
     if handler then
-      if log.trace() then
+      log.trace('server_request: found handler for', method)
-        log.trace('server_request: found handler for', method)
-      end
       return handler(nil, params, { method = method, client_id = client_id })
     end
-    if log.warn() then
+    log.warn('server_request: no handler found for', method)
-      log.warn('server_request: no handler found for', method)
-    end
     return nil, lsp.rpc_response_error(protocol.ErrorCodes.MethodNotFound)
   end
 
@@ -836,9 +828,7 @@ function lsp.start_client(config)
   --- @param code integer Error code
   --- @param err any Error arguments
   local function write_error(code, err)
-    if log.error() then
+    log.error(log_prefix, 'on_error', { code = lsp.client_errors[code], err = err })
-      log.error(log_prefix, 'on_error', { code = lsp.client_errors[code], err = err })
-    end
     err_message(log_prefix, ': Error ', lsp.client_errors[code], ': ', vim.inspect(err))
   end
 
@@ -854,9 +844,7 @@ function lsp.start_client(config)
     if config.on_error then
       local status, usererr = pcall(config.on_error, code, err)
       if not status then
-        if log.error() then
+        log.error(log_prefix, 'user on_error failed', { err = usererr })
-          log.error(log_prefix, 'user on_error failed', { err = usererr })
-        end
         err_message(log_prefix, ' user on_error failed: ', tostring(usererr))
       end
     end
@@ -1042,9 +1030,7 @@ function lsp.buf_attach_client(bufnr, client_id)
   })
   bufnr = resolve_bufnr(bufnr)
   if not api.nvim_buf_is_loaded(bufnr) then
-    if log.warn() then
+    log.warn(string.format('buf_attach_client called on unloaded buffer (id: %d): ', bufnr))
-      log.warn(string.format('buf_attach_client called on unloaded buffer (id: %d): ', bufnr))
-    end
     return false
   end
   local buffer_client_ids = all_buffer_active_clients[bufnr]
@@ -1504,9 +1490,7 @@ end
 --- - findstart=0: column where the completion starts, or -2 or -3
 --- - findstart=1: list of matches (actually just calls |complete()|)
 function lsp.omnifunc(findstart, base)
-  if log.debug() then
+  log.debug('omnifunc.findstart', { findstart = findstart, base = base })
-    log.debug('omnifunc.findstart', { findstart = findstart, base = base })
-  end
   return vim.lsp._completion.omnifunc(findstart, base)
 end
 

runtime/lua/vim/lsp/client.lua

@@ -244,9 +244,7 @@ function Client:initialize(cb)
     end
   end
 
-  if log.trace() then
+  log.trace(self._log_prefix, 'initialize_params', initialize_params)
-    log.trace(self._log_prefix, 'initialize_params', initialize_params)
-  end
 
   local rpc = self.rpc
 
@@ -278,13 +276,12 @@ function Client:initialize(cb)
         self:write_error(lsp.client_errors.ON_INIT_CALLBACK_ERROR, err)
       end
     end
-    if log.info() then
+
-      log.info(
+    log.info(
-        self._log_prefix,
+      self._log_prefix,
-        'server_capabilities',
+      'server_capabilities',
-        { server_capabilities = self.server_capabilities }
+      { server_capabilities = self.server_capabilities }
-      )
+    )
-    end
 
     cb()
   end)
@@ -340,9 +337,7 @@ function Client:_request(method, params, handler, bufnr)
   changetracking.flush(self, bufnr)
   local version = lsp.util.buf_versions[bufnr]
   bufnr = resolve_bufnr(bufnr)
-  if log.debug() then
+  log.debug(self._log_prefix, 'client.request', self.id, method, params, handler, bufnr)
-    log.debug(self._log_prefix, 'client.request', self.id, method, params, handler, bufnr)
-  end
   local success, request_id = self.rpc.request(method, params, function(err, result)
     local context = {
       method = method,
@@ -635,9 +630,7 @@ end
 --- @param code integer Error code
 --- @param err any Error arguments
 function Client:write_error(code, err)
-  if log.error() then
+  log.error(self._log_prefix, 'on_error', { code = lsp.client_errors[code], err = err })
-    log.error(self._log_prefix, 'on_error', { code = lsp.client_errors[code], err = err })
-  end
   err_message(self._log_prefix, ': Error ', lsp.client_errors[code], ': ', vim.inspect(err))
 end
 

runtime/lua/vim/lsp/codelens.lua

@@ -262,9 +262,7 @@ end
 function M.on_codelens(err, result, ctx, _)
   if err then
     active_refreshes[assert(ctx.bufnr)] = nil
-    if log.error() then
+    log.error('codelens', err)
-      log.error('codelens', err)
-    end
     return
   end
 

runtime/lua/vim/lsp/diagnostic.lua

@@ -35,7 +35,7 @@ local function severity_vim_to_lsp(severity)
   return severity
 end
 
----@param lines string[]
+---@param lines string[]?
 ---@param lnum integer
 ---@param col integer
 ---@param offset_encoding string
@@ -55,7 +55,7 @@ local function line_byte_from_position(lines, lnum, col, offset_encoding)
 end
 
 ---@param bufnr integer
----@return string[]
+---@return string[]?
 local function get_buf_lines(bufnr)
   if vim.api.nvim_buf_is_loaded(bufnr) then
     return vim.api.nvim_buf_get_lines(bufnr, 0, -1, false)

runtime/lua/vim/lsp/handlers.lua

@@ -413,9 +413,7 @@ M[ms.textDocument_hover] = M.hover
 ---(`textDocument/definition` can return `Location` or `Location[]`
 local function location_handler(_, result, ctx, config)
   if result == nil or vim.tbl_isempty(result) then
-    if log.info() then
+    log.info(ctx.method, 'No location found')
-      log.info(ctx.method, 'No location found')
-    end
     return nil
   end
   local client = assert(vim.lsp.get_client_by_id(ctx.client_id))
@@ -649,13 +647,14 @@ end
 -- Add boilerplate error validation and logging for all of these.
 for k, fn in pairs(M) do
   M[k] = function(err, result, ctx, config)
-    local _ = log.trace()
+    if log.trace() then
-      and log.trace('default_handler', ctx.method, {
+      log.trace('default_handler', ctx.method, {
         err = err,
         result = result,
         ctx = vim.inspect(ctx),
         config = config,
       })
+    end
 
     if err then
       -- LSP spec:

runtime/lua/vim/lsp/inlay_hint.lua

@@ -22,9 +22,7 @@ local augroup = api.nvim_create_augroup('vim_lsp_inlayhint', {})
 ---@private
 function M.on_inlayhint(err, result, ctx, _)
   if err then
-    if log.error() then
+    log.error('inlayhint', err)
-      log.error('inlayhint', err)
-    end
     return
   end
   local bufnr = assert(ctx.bufnr)

runtime/lua/vim/lsp/log.lua

@@ -12,131 +12,131 @@ log.levels = vim.deepcopy(vim.log.levels)
 
 -- Default log level is warn.
 local current_log_level = log.levels.WARN
+
 local log_date_format = '%F %H:%M:%S'
-local format_func = function(arg)
+
+local function format_func(arg)
   return vim.inspect(arg, { newline = '' })
 end
 
-do
+local function notify(msg, level)
-  local function notify(msg, level)
+  if vim.in_fast_event() then
-    if vim.in_fast_event() then
+    vim.schedule(function()
-      vim.schedule(function()
-        vim.notify(msg, level)
-      end)
-    else
       vim.notify(msg, level)
-    end
+    end)
-  end
+  else
-
+    vim.notify(msg, level)
-  local path_sep = vim.uv.os_uname().version:match('Windows') and '\\' or '/'
-  local function path_join(...)
-    return table.concat(vim.tbl_flatten({ ... }), path_sep)
-  end
-  local logfilename = path_join(vim.fn.stdpath('log'), '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'), 'p')
-
-  --- Returns the log filename.
-  ---@return string log filename
-  function log.get_filename()
-    return logfilename
-  end
-
-  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, vim.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
-  end
-
-  for level, levelnr in pairs(log.levels) do
-    -- Also export the log level on the root object.
-    log[level] = levelnr
-    -- FIXME: DOC
-    -- Should be exposed in the vim docs.
-    --
-    -- Set the lowercase name as the main use function.
-    -- If called without arguments, it will check whether the log level is
-    -- greater than or equal to this one. When called with arguments, it will
-    -- log at that level (if applicable, it is checked either way).
-    --
-    -- Recommended usage:
-    -- ```
-    -- if log.warn() then
-    --   log.warn("123")
-    -- end
-    -- ```
-    --
-    -- This way you can avoid string allocations if the log level isn't high enough.
-    if level ~= 'OFF' then
-      log[level:lower()] = function(...)
-        local argc = select('#', ...)
-        if levelnr < current_log_level then
-          return false
-        end
-        if argc == 0 then
-          return true
-        end
-        if not open_logfile() then
-          return false
-        end
-        local info = debug.getinfo(2, 'Sl')
-        local header = string.format(
-          '[%s][%s] ...%s:%s',
-          level,
-          os.date(log_date_format),
-          string.sub(info.short_src, #info.short_src - 15),
-          info.currentline
-        )
-        local parts = { header }
-        for i = 1, argc do
-          local arg = select(i, ...)
-          if arg == nil then
-            table.insert(parts, 'nil')
-          else
-            table.insert(parts, format_func(arg))
-          end
-        end
-        logfile:write(table.concat(parts, '\t'), '\n')
-        logfile:flush()
-      end
-    end
   end
 end
 
--- This is put here on purpose after the loop above so that it doesn't
+local logfilename = vim.fs.joinpath(vim.fn.stdpath('log'), 'lsp.log')
--- interfere with iterating the levels
+
+-- 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'), 'p')
+
+--- Returns the log filename.
+---@return string log filename
+function log.get_filename()
+  return logfilename
+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, vim.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
+end
+
+for level, levelnr in pairs(log.levels) do
+  -- Also export the log level on the root object.
+  log[level] = levelnr
+end
+
 vim.tbl_add_reverse_lookup(log.levels)
 
+--- @param level string
+--- @param levelnr integer
+--- @return fun(...:any): boolean?
+local function create_logger(level, levelnr)
+  return function(...)
+    if levelnr < current_log_level then
+      return false
+    end
+    local argc = select('#', ...)
+    if argc == 0 then
+      return true
+    end
+    if not open_logfile() then
+      return false
+    end
+    local info = debug.getinfo(2, 'Sl')
+    local header = string.format(
+      '[%s][%s] ...%s:%s',
+      level,
+      os.date(log_date_format),
+      info.short_src:sub(-16),
+      info.currentline
+    )
+    local parts = { header }
+    for i = 1, argc do
+      local arg = select(i, ...)
+      table.insert(parts, arg == nil and 'nil' or format_func(arg))
+    end
+    assert(logfile)
+    logfile:write(table.concat(parts, '\t'), '\n')
+    logfile:flush()
+  end
+end
+
+-- If called without arguments, it will check whether the log level is
+-- greater than or equal to this one. When called with arguments, it will
+-- log at that level (if applicable, it is checked either way).
+
+--- @nodoc
+log.debug = create_logger('DEBUG', vim.log.levels.DEBUG)
+
+--- @nodoc
+log.error = create_logger('ERROR', vim.log.levels.ERROR)
+
+--- @nodoc
+log.info = create_logger('INFO', vim.log.levels.INFO)
+
+--- @nodoc
+log.trace = create_logger('TRACE', vim.log.levels.TRACE)
+
+--- @nodoc
+log.warn = create_logger('WARN', vim.log.levels.WARN)
+
 --- Sets the current log level.
 ---@param level (string|integer) One of `vim.lsp.log.levels`
 function log.set_level(level)

runtime/lua/vim/lsp/rpc.lua

@@ -26,24 +26,6 @@ local function format_message_with_content_length(message)
   })
 end
 
-local function log_error(...)
-  if log.error() then
-    log.error(...)
-  end
-end
-
-local function log_info(...)
-  if log.info() then
-    log.info(...)
-  end
-end
-
-local function log_debug(...)
-  if log.debug() then
-    log.debug(...)
-  end
-end
-
 ---@class vim.lsp.rpc.Headers: {string: any}
 ---@field content_length integer
 
@@ -65,7 +47,7 @@ local function parse_headers(header)
       key = key:lower():gsub('%-', '_') --- @type string
       headers[key] = value
     else
-      log_error('invalid header line %q', line)
+      log.error('invalid header line %q', line)
       error(string.format('invalid header line %q', line))
     end
   end
@@ -224,7 +206,7 @@ local default_dispatchers = {
   ---@param method string The invoked LSP method
   ---@param params table Parameters for the invoked LSP method
   notification = function(method, params)
-    log_debug('notification', method, params)
+    log.debug('notification', method, params)
   end,
 
   --- Default dispatcher for requests sent to an LSP server.
@@ -234,7 +216,7 @@ local default_dispatchers = {
   ---@return any result (always nil for the default dispatchers)
   ---@return lsp.ResponseError error `vim.lsp.protocol.ErrorCodes.MethodNotFound`
   server_request = function(method, params)
-    log_debug('server_request', method, params)
+    log.debug('server_request', method, params)
     return nil, M.rpc_response_error(protocol.ErrorCodes.MethodNotFound)
   end,
 
@@ -243,7 +225,7 @@ local default_dispatchers = {
   ---@param code integer Exit code
   ---@param signal integer Number describing the signal used to terminate (if any)
   on_exit = function(code, signal)
-    log_info('client_exit', { code = code, signal = signal })
+    log.info('client_exit', { code = code, signal = signal })
   end,
 
   --- Default dispatcher for client errors.
@@ -251,7 +233,7 @@ local default_dispatchers = {
   ---@param code integer Error code
   ---@param err any Details about the error
   on_error = function(code, err)
-    log_error('client_error:', M.client_errors[code], err)
+    log.error('client_error:', M.client_errors[code], err)
   end,
 }
 
@@ -297,7 +279,7 @@ local Client = {}
 
 ---@private
 function Client:encode_and_send(payload)
-  log_debug('rpc.send', payload)
+  log.debug('rpc.send', payload)
   if self.transport.is_closing() then
     return false
   end
@@ -419,7 +401,7 @@ function Client:handle_body(body)
     self:on_error(M.client_errors.INVALID_SERVER_JSON, decoded)
     return
   end
-  log_debug('rpc.receive', decoded)
+  log.debug('rpc.receive', decoded)
 
   if type(decoded.method) == 'string' and decoded.id then
     local err --- @type lsp.ResponseError|nil
@@ -434,7 +416,7 @@ function Client:handle_body(body)
           decoded.method,
           decoded.params
         )
-        log_debug(
+        log.debug(
           'server_request: callback result',
           { status = status, result = result, err = err }
         )
@@ -490,7 +472,7 @@ function Client:handle_body(body)
     if decoded.error then
       local mute_error = false
       if decoded.error.code == protocol.ErrorCodes.RequestCancelled then
-        log_debug('Received cancellation ack', decoded)
+        log.debug('Received cancellation ack', decoded)
         mute_error = true
       end
 
@@ -526,7 +508,7 @@ function Client:handle_body(body)
       )
     else
       self:on_error(M.client_errors.NO_RESULT_CALLBACK_FOUND, decoded)
-      log_error('No callback found for server response id ' .. result_id)
+      log.error('No callback found for server response id ' .. result_id)
     end
   elseif type(decoded.method) == 'string' then
     -- Notification
@@ -773,7 +755,7 @@ end
 ---   - `is_closing()` returns a boolean indicating if the RPC is closing.
 ---   - `terminate()` terminates the RPC client.
 function M.start(cmd, cmd_args, dispatchers, extra_spawn_params)
-  log_info('Starting RPC client', { cmd = cmd, args = cmd_args, extra = extra_spawn_params })
+  log.info('Starting RPC client', { cmd = cmd, args = cmd_args, extra = extra_spawn_params })
 
   validate({
     cmd = { cmd, 's' },
@@ -813,7 +795,7 @@ function M.start(cmd, cmd_args, dispatchers, extra_spawn_params)
 
   local stderr_handler = function(_, chunk)
     if chunk then
-      log_error('rpc', cmd, 'stderr', chunk)
+      log.error('rpc', cmd, 'stderr', chunk)
     end
   end