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

runtime/lua/vim/lsp.lua

@@ -154,7 +154,7 @@ local function validate_client_config(config)
     callbacks       = { config.callbacks, "t", true };
     capabilities    = { config.capabilities, "t", true };
     cmd_cwd         = { config.cmd_cwd, optional_validator(is_dir), "directory" };
-    cmd_env         = { config.cmd_env, "f", true };
+    cmd_env         = { config.cmd_env, "t", true };
     name            = { config.name, 's', true };
     on_error        = { config.on_error, "f", true };
     on_exit         = { config.on_exit, "f", true };

runtime/lua/vim/lsp/rpc.lua

@@ -33,39 +33,26 @@ local function convert_NIL(v)
   return v
 end
 
--- If a dictionary is passed in, turn it into a list of string of "k=v"
+--- Merges current process env with the given env and returns the result as
--- Accepts a table which can be composed of k=v strings or map-like
+--- a list of "k=v" strings.
--- specification, such as:
+---
---
+--- Example:
--- ```
+---
--- {
+---      { PRODUCTION="false", PATH="/usr/bin/", PORT=123, HOST="0.0.0.0", }
---   "PRODUCTION=false";
+---   => { "PRODUCTION=false", "PATH=/usr/bin/", "PORT=123", "HOST=0.0.0.0", }
---   "PATH=/usr/bin/";
+local function env_merge(env)
---   PORT = 123;
+  if env == nil then
---   HOST = "0.0.0.0";
+    return env
--- }
--- ```
---
--- Non-string values will be cast with `tostring`
-local function force_env_list(final_env)
-  if final_env then
-    local env = final_env
-    final_env = {}
-    for k,v in pairs(env) do
-      -- If it's passed in as a dict, then convert to list of "k=v"
-      if type(k) == "string" then
-        table.insert(final_env, k..'='..tostring(v))
-      elseif type(v) == 'string' then
-        table.insert(final_env, v)
-      else
-        -- TODO is this right or should I exception here?
-        -- Try to coerce other values to string.
-        table.insert(final_env, tostring(v))
   end
+  -- Merge.
+  env = vim.tbl_extend('force', vim.fn.environ(), env)
+  local final_env = {}
+  for k,v in pairs(env) do
+    assert(type(k) == 'string', 'env must be a dict')
+    table.insert(final_env, k..'='..tostring(v))
   end
   return final_env
 end
-end
 
 local function format_message_with_content_length(encoded_message)
   return table.concat {
@@ -262,7 +249,7 @@ local function create_and_start_client(cmd, cmd_args, handlers, extra_spawn_para
       if spawn_params.cwd then
         assert(is_dir(spawn_params.cwd), "cwd must be a directory")
       end
-      spawn_params.env = force_env_list(extra_spawn_params.env)
+      spawn_params.env = env_merge(extra_spawn_params.env)
     end
     handle, pid = uv.spawn(cmd, spawn_params, onexit)
   end

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;
   }

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)

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()

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.
+-- Logs to $NVIM_LOG_FILE.
-local function json_encode(data)
+--
-  local status, result = pcall(vim.fn.json_encode, data)
+-- TODO(justinmk): remove after https://github.com/neovim/neovim/pull/7062
-  if status then
+local function log(loglevel, area, msg)
-    return result
+  vim.fn.writefile(
-  else
+    {string.format('%s %s: %s', loglevel, area, msg)},
-    return nil, result
+    vim.env.NVIM_LOG_FILE,
-  end
+    'a')
-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
 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)

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"
+-- Fake LSP server.
-if iswin() then
+local fake_lsp_code = 'test/functional/fixtures/fake-lsp-server.lua'
-  lsp_test_rpc_server_file = lsp_test_rpc_server_file:gsub("/", "\\")
+local fake_lsp_logfile = 'Xtest-fake-lsp.log'
-end
 
-local function test_rpc_server_setup(test_name, timeout_ms)
+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 = 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")

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()
+function module.read_nvim_log(logfile, ci_rename)
-  local logfile = os.getenv('NVIM_LOG_FILE') or '.nvimlog'
+  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

third-party/cmake/BuildLuarocks.cmake

@@ -217,10 +217,10 @@ if(USE_BUNDLED_BUSTED)
   endif()
   add_custom_target(luv DEPENDS ${ROCKS_DIR}/luv)
 
-  # nvim-client
+  # nvim-client: https://github.com/neovim/lua-client
   add_custom_command(OUTPUT ${ROCKS_DIR}/nvim-client
     COMMAND ${LUAROCKS_BINARY}
-    ARGS build nvim-client 0.2.0-1 ${LUAROCKS_BUILDARGS}
+    ARGS build nvim-client 0.2.2-1 ${LUAROCKS_BUILDARGS}
     DEPENDS luv)
   add_custom_target(nvim-client DEPENDS ${ROCKS_DIR}/nvim-client)