test/LSP: dump logs on error

This will help debug CI flakey failures.

TODO: helpers.assert_log()  -- Explicitly check contents of the logfile.
This commit is contained in:
Justin M. Keyes 2020-02-08 18:08:02 -08:00
parent 1eb0f5371a
commit 4cf48dc329
2 changed files with 54 additions and 39 deletions

View File

@ -5,8 +5,8 @@ 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 insert = helpers.insert
local iswin = helpers.iswin
local retry = helpers.retry
local NIL = helpers.NIL
@ -14,17 +14,24 @@ 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 fake_lsp_server_file = 'test/functional/fixtures/fake-lsp-server.lua'
-- 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 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 = 'Xtest-fake-lsp-server.log'
NVIM_LOG_FILE = logfile;
};
cmd = {
vim.v.progpath, '-Es', '-u', 'NONE', '--headless',
@ -48,7 +55,7 @@ local function fake_lsp_server_setup(test_name, timeout_ms)
vim.rpcnotify(1, "exit", ...)
end;
}
]=], test_name, fake_lsp_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)
@ -114,11 +121,11 @@ 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 = 'Xtest-fake-lsp-server.log'
NVIM_LOG_FILE = logfile;
};
cmd = {
vim.v.progpath, '-Es', '-u', 'NONE', '--headless',
@ -129,7 +136,7 @@ describe('LSP', function()
}
end
TEST_CLIENT1 = test__start_client()
]=], test_name, fake_lsp_server_file)
]=], test_name, fake_lsp_code, fake_lsp_logfile)
end)
after_each(function()
@ -198,8 +205,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)
@ -220,8 +227,8 @@ describe('LSP', function()
client.stop()
end;
on_exit = function(code, signal)
eq(101, code, "exit code") -- See fake-lsp-server.lua
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")
end;
on_callback = function(...)
eq(table.remove(expected_callbacks), {...}, "expected callback")
@ -242,8 +249,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")
@ -261,8 +268,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")
@ -301,8 +308,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")
@ -344,8 +351,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
@ -387,8 +394,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
@ -430,8 +437,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
@ -479,8 +486,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
@ -528,8 +535,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
@ -577,8 +584,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
@ -621,8 +628,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
@ -672,8 +679,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
@ -715,8 +722,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")

View File

@ -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
@ -737,10 +745,10 @@ function module.isCI(name)
end
-- Gets the contents of $NVIM_LOG_FILE for printing to the build log.
-- Gets the contents of `logfile` for printing to the build log.
-- 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)
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 {}