feat(lsp): improve logging (#15636)

* Simplify rpc encode/decode messages to rpc.send/rcp.receive
* Make missing handlers message throw a warning
* Clean up formatting style in log
* Move all non-RPC loop messages to trace instead of debug
* Add format func option to log to allow newlines in per log entry

4 files changed, 27 insertions, 14 deletions

diff --git a/runtime/lua/vim/lsp.lua b/runtime/lua/vim/lsp.lua
index 6365091668..0c51321d32 100644
--- a/runtime/lua/vim/lsp.lua
+++ b/runtime/lua/vim/lsp.lua
@@ -677,7 +677,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)
-    local _ = log.debug() and log.debug('notification', method, params)
+    local _ = log.trace() and log.trace('notification', method, params)
     local handler = resolve_handler(method)
     if handler then
       -- Method name is provided here for convenience.
@@ -691,13 +691,13 @@ function lsp.start_client(config)
   --@param method (string) LSP method name
   --@param params (table) The parameters for that method
   function dispatch.server_request(method, params)
-    local _ = log.debug() and log.debug('server_request', method, params)
+    local _ = log.trace() and log.trace('server_request', method, params)
     local handler = resolve_handler(method)
     if handler then
-      local _ = log.debug() and log.debug("server_request: found handler for", method)
+      local _ = log.trace() and log.trace("server_request: found handler for", method)
       return handler(nil, params, {method=method, client_id=client_id})
     end
-    local _ = log.debug() and log.debug("server_request: no handler found for", method)
+    local _ = log.warn() and log.warn("server_request: no handler found for", method)
     return nil, lsp.rpc_response_error(protocol.ErrorCodes.MethodNotFound)
   end
 
@@ -824,7 +824,7 @@ function lsp.start_client(config)
       -- TODO(ashkan) handle errors here.
       pcall(config.before_init, initialize_params, config)
     end
-    local _ = log.debug() and log.debug(log_prefix, "initialize_params", initialize_params)
+    local _ = log.trace() and log.trace(log_prefix, "initialize_params", initialize_params)
     rpc.request('initialize', initialize_params, function(init_err, result)
       assert(not init_err, tostring(init_err))
       assert(result, "server sent empty result")
diff --git a/runtime/lua/vim/lsp/handlers.lua b/runtime/lua/vim/lsp/handlers.lua
index 5ee2ddf86c..475b345e84 100644
--- a/runtime/lua/vim/lsp/handlers.lua
+++ b/runtime/lua/vim/lsp/handlers.lua
@@ -419,7 +419,7 @@ M['window/logMessage'] = function(_, result, ctx, _)
     log.error(message)
   elseif message_type == protocol.MessageType.Warning then
     log.warn(message)
-  elseif message_type == protocol.MessageType.Info then
+  elseif message_type == protocol.MessageType.Info or  message_type == protocol.MessageType.Log then
     log.info(message)
   else
     log.debug(message)
@@ -449,7 +449,7 @@ 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.debug() and log.debug('default_handler', ctx.method, {
+    local _ = log.trace() and log.trace('default_handler', ctx.method, {
       err = err, result = result, ctx=vim.inspect(ctx), config = config
     })
 
diff --git a/runtime/lua/vim/lsp/log.lua b/runtime/lua/vim/lsp/log.lua
index 73fafb9715..2848b380be 100644
--- a/runtime/lua/vim/lsp/log.lua
+++ b/runtime/lua/vim/lsp/log.lua
@@ -14,7 +14,8 @@ log.levels = vim.deepcopy(vim.log.levels)
 
 -- Default log level is warn.
 local current_log_level = log.levels.WARN
-local log_date_format = "%FT%H:%M:%S%z"
+local log_date_format = "%F %H:%M:%S"
+local format_func = function(arg) return vim.inspect(arg, {newline=''}) end
 
 do
   local path_sep = vim.loop.os_uname().version:match("Windows") and "\\" or "/"
@@ -33,7 +34,7 @@ do
   vim.fn.mkdir(vim.fn.stdpath('cache'), "p")
   local logfile = assert(io.open(logfilename, "a+"))
   -- Start message for logging
-  logfile:write(string.format("[ START ] %s ] LSP logging initiated\n", os.date(log_date_format)))
+  logfile:write(string.format("[START][%s] LSP logging initiated\n", os.date(log_date_format)))
   for level, levelnr in pairs(log.levels) do
     -- Also export the log level on the root object.
     log[level] = levelnr
@@ -56,14 +57,14 @@ do
       if levelnr < current_log_level then return false end
       if argc == 0 then return true end
       local info = debug.getinfo(2, "Sl")
-      local fileinfo = string.format("%s:%s", info.short_src, info.currentline)
-      local parts = { table.concat({"[", level, "]", os.date(log_date_format), "]", fileinfo, "]"}, " ") }
+      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, vim.inspect(arg, {newline=''}))
+          table.insert(parts, format_func(arg))
         end
       end
       logfile:write(table.concat(parts, '\t'), "\n")
@@ -88,6 +89,18 @@ function log.set_level(level)
   end
 end
 
+--- Gets the current log level.
+function log.get_level()
+  return current_log_level
+end
+
+--- Sets formatting function used to format logs
+---@param handle function function to apply to logging arguments, pass vim.inspect for multi-line formatting
+function log.set_format_func(handle)
+  assert(handle == vim.inspect or type(handle) == 'function', "handle must be a function")
+  format_func = handle
+end
+
 --- Checks whether the level is sufficient for logging.
 --@param level number log level
 --@returns (bool) true if would log, false if not
diff --git a/runtime/lua/vim/lsp/rpc.lua b/runtime/lua/vim/lsp/rpc.lua
index 4c5f02af9d..f5d1cbd2d5 100644
--- a/runtime/lua/vim/lsp/rpc.lua
+++ b/runtime/lua/vim/lsp/rpc.lua
@@ -392,7 +392,7 @@ local function start(cmd, cmd_args, dispatchers, extra_spawn_params)
   --@param payload (table) Converted into a JSON string, see |json_encode()|
   --@returns true if the payload could be scheduled, false if the main event-loop is in the process of closing.
   local function encode_and_send(payload)
-    local _ = log.debug() and log.debug("rpc.send.payload", payload)
+    local _ = log.debug() and log.debug("rpc.send", payload)
     if handle == nil or handle:is_closing() then return false end
     -- TODO(ashkan) remove this once we have a Lua json_encode
     schedule(function()
@@ -493,7 +493,7 @@ local function start(cmd, cmd_args, dispatchers, extra_spawn_params)
       -- on_error(client_errors.INVALID_SERVER_JSON, err)
       return
     end
-    local _ = log.debug() and log.debug("decoded", decoded)
+    local _ = log.debug() and log.debug("rpc.receive", decoded)
 
     if type(decoded.method) == 'string' and decoded.id then
       -- Server Request