Merge #11837 'LSP: fixes, improve test visibility'

5 files changed, 101 insertions, 58 deletions

diff --git a/test/busted/outputHandlers/TAP.lua b/test/busted/outputHandlers/TAP.lua
index 8dc4ff55b6..5de48c0ad3 100644
--- a/test/busted/outputHandlers/TAP.lua
+++ b/test/busted/outputHandlers/TAP.lua
@@ -7,7 +7,7 @@ return function(options)
   local handler = require 'busted.outputHandlers.TAP'(options)
 
   local suiteEnd = function()
-    io.write(global_helpers.read_nvim_log())
+    io.write(global_helpers.read_nvim_log(nil, true))
     return nil, true
   end
   busted.subscribe({ 'suite', 'end' }, suiteEnd)
diff --git a/test/busted/outputHandlers/nvim.lua b/test/busted/outputHandlers/nvim.lua
index 8f3aad776e..5456e9ca98 100644
--- a/test/busted/outputHandlers/nvim.lua
+++ b/test/busted/outputHandlers/nvim.lua
@@ -196,7 +196,7 @@ return function(options)
     local tests = (testCount == 1 and 'test' or 'tests')
     local files = (fileCount == 1 and 'file' or 'files')
     io.write(globalTeardown)
-    io.write(global_helpers.read_nvim_log())
+    io.write(global_helpers.read_nvim_log(nil, true))
     io.write(suiteEndString:format(testCount, tests, fileCount, files, elapsedTime_ms))
     io.write(getSummaryString())
     io.flush()
diff --git a/test/functional/fixtures/lsp-test-rpc-server.lua b/test/functional/fixtures/fake-lsp-server.lua
index 798883ced0..dca7f35923 100644
--- a/test/functional/fixtures/lsp-test-rpc-server.lua
+++ b/test/functional/fixtures/fake-lsp-server.lua
@@ -1,23 +1,14 @@
 local protocol = require 'vim.lsp.protocol'
 
--- Internal utility methods.
 
--- TODO replace with a better implementation.
-local function json_encode(data)
-  local status, result = pcall(vim.fn.json_encode, data)
-  if status then
-    return result
-  else
-    return nil, result
-  end
-end
-local function json_decode(data)
-  local status, result = pcall(vim.fn.json_decode, data)
-  if status then
-    return result
-  else
-    return nil, result
-  end
+-- Logs to $NVIM_LOG_FILE.
+--
+-- TODO(justinmk): remove after https://github.com/neovim/neovim/pull/7062
+local function log(loglevel, area, msg)
+  vim.fn.writefile(
+    {string.format('%s %s: %s', loglevel, area, msg)},
+    vim.env.NVIM_LOG_FILE,
+    'a')
 end
 
 local function message_parts(sep, ...)
@@ -49,16 +40,14 @@ local function format_message_with_content_length(encoded_message)
   }
 end
 
--- Server utility methods.
-
 local function read_message()
   local line = io.read("*l")
   local length = line:lower():match("content%-length:%s*(%d+)")
-  return assert(json_decode(io.read(2 + length):sub(2)), "read_message.json_decode")
+  return vim.fn.json_decode(io.read(2 + length):sub(2))
 end
 
 local function send(payload)
-  io.stdout:write(format_message_with_content_length(json_encode(payload)))
+  io.stdout:write(format_message_with_content_length(vim.fn.json_encode(payload)))
 end
 
 local function respond(id, err, result)
@@ -390,7 +379,7 @@ function tests.basic_check_buffer_open_and_change_incremental()
   }
 end
 
-function tests.basic_check_buffer_open_and_change_incremental_editting()
+function tests.basic_check_buffer_open_and_change_incremental_editing()
   skeleton {
     on_init = function(params)
       local expected_capabilities = protocol.make_client_capabilities()
@@ -443,6 +432,7 @@ local kill_timer = vim.loop.new_timer()
 kill_timer:start(_G.TIMEOUT or 1e3, 0, function()
   kill_timer:stop()
   kill_timer:close()
+  log('ERROR', 'LSP', 'TIMEOUT')
   io.stderr:write("TIMEOUT")
   os.exit(100)
 end)
@@ -453,7 +443,8 @@ local status, err = pcall(assert(tests[test_name], "Test not found"))
 kill_timer:stop()
 kill_timer:close()
 if not status then
+  log('ERROR', 'LSP', tostring(err))
   io.stderr:write(err)
-  os.exit(1)
+  os.exit(101)
 end
 os.exit(0)
diff --git a/test/functional/plugin/lsp_spec.lua b/test/functional/plugin/lsp_spec.lua
index 4829a33861..03e516d6f6 100644
--- a/test/functional/plugin/lsp_spec.lua
+++ b/test/functional/plugin/lsp_spec.lua
@@ -1,12 +1,14 @@
 local helpers = require('test.functional.helpers')(after_each)
 
+local assert_log = helpers.assert_log
 local clear = helpers.clear
 local buf_lines = helpers.buf_lines
 local dedent = helpers.dedent
 local exec_lua = helpers.exec_lua
 local eq = helpers.eq
+local eq_dumplog = helpers.eq_dumplog
+local pesc = helpers.pesc
 local insert = helpers.insert
-local iswin = helpers.iswin
 local retry = helpers.retry
 local NIL = helpers.NIL
 
@@ -14,20 +16,27 @@ local NIL = helpers.NIL
 -- yield.
 local run, stop = helpers.run, helpers.stop
 
+-- TODO(justinmk): hangs on Windows https://github.com/neovim/neovim/pull/11837
 if helpers.pending_win32(pending) then return end
 
-local lsp_test_rpc_server_file = "test/functional/fixtures/lsp-test-rpc-server.lua"
-if iswin() then
-  lsp_test_rpc_server_file = lsp_test_rpc_server_file:gsub("/", "\\")
-end
+-- Fake LSP server.
+local fake_lsp_code = 'test/functional/fixtures/fake-lsp-server.lua'
+local fake_lsp_logfile = 'Xtest-fake-lsp.log'
+
+teardown(function()
+  os.remove(fake_lsp_logfile)
+end)
 
-local function test_rpc_server_setup(test_name, timeout_ms)
+local function fake_lsp_server_setup(test_name, timeout_ms)
   exec_lua([=[
     lsp = require('vim.lsp')
-    local test_name, fixture_filename, timeout = ...
+    local test_name, fixture_filename, logfile, timeout = ...
     TEST_RPC_CLIENT_ID = lsp.start_client {
+      cmd_env = {
+        NVIM_LOG_FILE = logfile;
+      };
       cmd = {
-        vim.api.nvim_get_vvar("progpath"), '-Es', '-u', 'NONE', '--headless',
+        vim.v.progpath, '-Es', '-u', 'NONE', '--headless',
         "-c", string.format("lua TEST_NAME = %q", test_name),
         "-c", string.format("lua TIMEOUT = %d", timeout),
         "-c", "luafile "..fixture_filename,
@@ -48,13 +57,13 @@ local function test_rpc_server_setup(test_name, timeout_ms)
         vim.rpcnotify(1, "exit", ...)
       end;
     }
-  ]=], test_name, lsp_test_rpc_server_file, timeout_ms or 1e3)
+  ]=], test_name, fake_lsp_code, fake_lsp_logfile, timeout_ms or 1e3)
 end
 
 local function test_rpc_server(config)
   if config.test_name then
     clear()
-    test_rpc_server_setup(config.test_name, config.timeout_ms or 1e3)
+    fake_lsp_server_setup(config.test_name, config.timeout_ms or 1e3)
   end
   local client = setmetatable({}, {
     __index = function(_, name)
@@ -114,11 +123,14 @@ describe('LSP', function()
       local test_name = "basic_init"
       exec_lua([=[
         lsp = require('vim.lsp')
-        local test_name, fixture_filename = ...
+        local test_name, fixture_filename, logfile = ...
         function test__start_client()
           return lsp.start_client {
+            cmd_env = {
+              NVIM_LOG_FILE = logfile;
+            };
             cmd = {
-              vim.api.nvim_get_vvar("progpath"), '-Es', '-u', 'NONE', '--headless',
+              vim.v.progpath, '-Es', '-u', 'NONE', '--headless',
               "-c", string.format("lua TEST_NAME = %q", test_name),
               "-c", "luafile "..fixture_filename;
             };
@@ -126,7 +138,7 @@ describe('LSP', function()
           }
         end
         TEST_CLIENT1 = test__start_client()
-      ]=], test_name, lsp_test_rpc_server_file)
+      ]=], test_name, fake_lsp_code, fake_lsp_logfile)
     end)
 
     after_each(function()
@@ -195,7 +207,8 @@ describe('LSP', function()
         end;
         -- If the program timed out, then code will be nil.
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         -- Note that NIL must be used here.
         -- on_callback(err, method, result, client_id)
@@ -216,7 +229,10 @@ describe('LSP', function()
           client.stop()
         end;
         on_exit = function(code, signal)
-          eq(1, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 101, code, "exit code")  -- See fake-lsp-server.lua
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
+          assert_log(pesc([[assert_eq failed: left == "\"shutdown\"", right == "\"test\""]]),
+            fake_lsp_logfile)
         end;
         on_callback = function(...)
           eq(table.remove(expected_callbacks), {...}, "expected callback")
@@ -237,7 +253,8 @@ describe('LSP', function()
           client.notify('exit')
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(...)
           eq(table.remove(expected_callbacks), {...}, "expected callback")
@@ -255,7 +272,8 @@ describe('LSP', function()
           client.stop()
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(...)
           eq(table.remove(expected_callbacks), {...}, "expected callback")
@@ -294,7 +312,8 @@ describe('LSP', function()
           client.notify('finish')
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           eq(table.remove(expected_callbacks), {err, method, params, client_id}, "expected callback")
@@ -336,7 +355,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -378,7 +398,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -420,7 +441,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -468,7 +490,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -516,7 +539,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -536,7 +560,7 @@ describe('LSP', function()
     end)
 
     -- TODO(askhan) we don't support full for now, so we can disable these tests.
-    pending('should check the body and didChange incremental normal mode editting', function()
+    pending('should check the body and didChange incremental normal mode editing', function()
       local expected_callbacks = {
         {NIL, "shutdown", {}, 1};
         {NIL, "finish", {}, 1};
@@ -544,7 +568,7 @@ describe('LSP', function()
       }
       local client
       test_rpc_server {
-        test_name = "basic_check_buffer_open_and_change_incremental_editting";
+        test_name = "basic_check_buffer_open_and_change_incremental_editing";
         on_setup = function()
           exec_lua [[
             BUFFER = vim.api.nvim_create_buf(false, true)
@@ -564,7 +588,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -607,7 +632,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -657,7 +683,8 @@ describe('LSP', function()
           ]]
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           if method == 'start' then
@@ -699,7 +726,8 @@ describe('LSP', function()
           client.stop(true)
         end;
         on_exit = function(code, signal)
-          eq(0, code, "exit code") eq(0, signal, "exit signal")
+          eq_dumplog(fake_lsp_logfile, 0, code, "exit code")
+          eq_dumplog(fake_lsp_logfile, 0, signal, "exit signal")
         end;
         on_callback = function(err, method, params, client_id)
           eq(table.remove(expected_callbacks), {err, method, params, client_id}, "expected callback")
diff --git a/test/helpers.lua b/test/helpers.lua
index 98f003f208..a31a7733bf 100644
--- a/test/helpers.lua
+++ b/test/helpers.lua
@@ -58,6 +58,14 @@ local check_logs_useless_lines = {
 function module.eq(expected, actual, context)
   return assert.are.same(expected, actual, context)
 end
+-- Like eq(), but includes tail of `logfile` in failure message.
+function module.eq_dumplog(logfile, expected, actual, context)
+  local status, rv = pcall(module.eq, expected, actual, context)
+  if not status then
+    local logtail = module.read_nvim_log(logfile)
+    error(string.format('%s\n%s', rv, logtail))
+  end
+end
 function module.neq(expected, actual, context)
   return assert.are_not.same(expected, actual, context)
 end
@@ -74,6 +82,22 @@ function module.matches(pat, actual)
   error(string.format('Pattern does not match.\nPattern:\n%s\nActual:\n%s', pat, actual))
 end
 
+--- Asserts that `pat` matches one or more lines in the tail of $NVIM_LOG_FILE.
+---
+--@param pat  (string) Lua pattern to search for in the log file.
+--@param logfile  (string, default=$NVIM_LOG_FILE) full path to log file.
+function module.assert_log(pat, logfile)
+  logfile = logfile or os.getenv('NVIM_LOG_FILE') or '.nvimlog'
+  local nrlines = 10
+  local lines = module.read_file_list(logfile, -nrlines) or {}
+  for _,line in ipairs(lines) do
+    if line:match(pat) then return end
+  end
+  local logtail = module.read_nvim_log(logfile)
+  error(string.format('Pattern %q not found in log (last %d lines): %s:\n%s',
+    pat, nrlines, logfile, logtail))
+end
+
 -- Invokes `fn` and returns the error string (may truncate full paths), or
 -- raises an error if `fn` succeeds.
 --
@@ -737,10 +761,10 @@ function module.isCI(name)
 
 end
 
--- Gets the contents of $NVIM_LOG_FILE for printing to the build log.
+-- Gets the (tail) contents of `logfile`.
 -- Also moves the file to "${NVIM_LOG_FILE}.displayed" on CI environments.
-function module.read_nvim_log()
-  local logfile = os.getenv('NVIM_LOG_FILE') or '.nvimlog'
+function module.read_nvim_log(logfile, ci_rename)
+  logfile = logfile or os.getenv('NVIM_LOG_FILE') or '.nvimlog'
   local is_ci = module.isCI()
   local keep = is_ci and 999 or 10
   local lines = module.read_file_list(logfile, -keep) or {}
@@ -751,7 +775,7 @@ function module.read_nvim_log()
     log = log..line..'\n'
   end
   log = log..('-'):rep(78)..'\n'
-  if is_ci then
+  if is_ci and ci_rename then
     os.rename(logfile, logfile .. '.displayed')
   end
   return log