test/LSP: assert contents of log file

6 files changed, 38 insertions, 8 deletions

diff --git a/src/nvim/msgpack_rpc/server.c b/src/nvim/msgpack_rpc/server.c
index 6168f097a7..062ea784ca 100644
--- a/src/nvim/msgpack_rpc/server.c
+++ b/src/nvim/msgpack_rpc/server.c
@@ -151,7 +151,7 @@ int server_start(const char *endpoint)
 
   result = socket_watcher_start(watcher, MAX_CONNECTIONS, connection_cb);
   if (result < 0) {
-    WLOG("Failed to start server: %s", uv_strerror(result));
+    WLOG("Failed to start server: %s: %s", uv_strerror(result), watcher->addr);
     socket_watcher_close(watcher, free_server);
     return result;
   }
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/fake-lsp-server.lua b/test/functional/fixtures/fake-lsp-server.lua
index cac590fd14..dca7f35923 100644
--- a/test/functional/fixtures/fake-lsp-server.lua
+++ b/test/functional/fixtures/fake-lsp-server.lua
@@ -1,6 +1,16 @@
 local protocol = require 'vim.lsp.protocol'
 
 
+-- 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, ...)
   local parts = {}
   for i = 1, select("#", ...) do
@@ -422,7 +432,7 @@ local kill_timer = vim.loop.new_timer()
 kill_timer:start(_G.TIMEOUT or 1e3, 0, function()
   kill_timer:stop()
   kill_timer:close()
-  -- TODO: log('TIMEOUT')
+  log('ERROR', 'LSP', 'TIMEOUT')
   io.stderr:write("TIMEOUT")
   os.exit(100)
 end)
@@ -433,7 +443,7 @@ local status, err = pcall(assert(tests[test_name], "Test not found"))
 kill_timer:stop()
 kill_timer:close()
 if not status then
-  -- TODO: log(err)
+  log('ERROR', 'LSP', tostring(err))
   io.stderr:write(err)
   os.exit(101)
 end
diff --git a/test/functional/plugin/lsp_spec.lua b/test/functional/plugin/lsp_spec.lua
index b2d00a400a..03e516d6f6 100644
--- a/test/functional/plugin/lsp_spec.lua
+++ b/test/functional/plugin/lsp_spec.lua
@@ -1,11 +1,13 @@
 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 retry = helpers.retry
 local NIL = helpers.NIL
@@ -229,6 +231,8 @@ describe('LSP', function()
         on_exit = function(code, 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")
diff --git a/test/helpers.lua b/test/helpers.lua
index d9e1f4a963..a31a7733bf 100644
--- a/test/helpers.lua
+++ b/test/helpers.lua
@@ -82,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.
 --
@@ -745,9 +761,9 @@ function module.isCI(name)
 
 end
 
--- Gets the contents of `logfile` 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(logfile)
+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
@@ -759,7 +775,7 @@ function module.read_nvim_log(logfile)
     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