Merge #21844 test: avoid noise in test logs

10 files changed, 95 insertions, 56 deletions

diff --git a/src/nvim/msgpack_rpc/server.c b/src/nvim/msgpack_rpc/server.c
index b1e033d9f1..1d75c208be 100644
--- a/src/nvim/msgpack_rpc/server.c
+++ b/src/nvim/msgpack_rpc/server.c
@@ -101,7 +101,7 @@ char *server_address_new(const char *name)
   xfree(dir);
 #endif
   if ((size_t)r >= sizeof(fmt)) {
-    ELOG("truncated server address");
+    ELOG("truncated server address: %.40s...", fmt);
   }
   return xstrdup(fmt);
 }
diff --git a/test/functional/api/server_notifications_spec.lua b/test/functional/api/server_notifications_spec.lua
index 833d54396b..53642858b2 100644
--- a/test/functional/api/server_notifications_spec.lua
+++ b/test/functional/api/server_notifications_spec.lua
@@ -1,4 +1,5 @@
 local helpers = require('test.functional.helpers')(after_each)
+local assert_log = helpers.assert_log
 local eq, clear, eval, command, nvim, next_msg =
   helpers.eq, helpers.clear, helpers.eval, helpers.command, helpers.nvim,
   helpers.next_msg
@@ -9,6 +10,8 @@ local is_ci = helpers.is_ci
 local assert_alive = helpers.assert_alive
 local skip = helpers.skip
 
+local testlog = 'Xtest-server-notify-log'
+
 describe('notify', function()
   local channel
 
@@ -17,6 +20,10 @@ describe('notify', function()
     channel = nvim('get_api_info')[1]
   end)
 
+  after_each(function()
+    os.remove(testlog)
+  end)
+
   describe('passing a valid channel id', function()
     it('sends the notification/args to the corresponding channel', function()
       eval('rpcnotify('..channel..', "test-event", 1, 2, 3)')
@@ -72,8 +79,12 @@ describe('notify', function()
   end)
 
   it('unsubscribe non-existing event #8745', function()
+    clear{env={
+      NVIM_LOG_FILE=testlog,
+    }}
     nvim('subscribe', 'event1')
     nvim('unsubscribe', 'doesnotexist')
+    assert_log("tried to unsubscribe unknown event 'doesnotexist'", testlog, 10)
     nvim('unsubscribe', 'event1')
     assert_alive()
   end)
diff --git a/test/functional/core/fileio_spec.lua b/test/functional/core/fileio_spec.lua
index bbf2202f0d..4e9891a4de 100644
--- a/test/functional/core/fileio_spec.lua
+++ b/test/functional/core/fileio_spec.lua
@@ -295,9 +295,7 @@ describe('tmpdir', function()
     clear({ env={ NVIM_LOG_FILE=testlog, TMPDIR=faketmp, } })
     matches(tmproot_pat, funcs.stdpath('run'))  -- Tickle vim_mktempdir().
     -- Assert that broken tmpdir root was handled.
-    retry(nil, 1000, function()
-      assert_log('tempdir root not a directory', testlog, 100)
-    end)
+    assert_log('tempdir root not a directory', testlog, 100)
 
     -- "…/nvim.<user>/" has wrong permissions:
     skip(is_os('win'), 'TODO(justinmk): need setfperm/getfperm on Windows. #8244')
@@ -308,9 +306,7 @@ describe('tmpdir', function()
     clear({ env={ NVIM_LOG_FILE=testlog, TMPDIR=faketmp, } })
     matches(tmproot_pat, funcs.stdpath('run'))  -- Tickle vim_mktempdir().
     -- Assert that broken tmpdir root was handled.
-    retry(nil, 1000, function()
-      assert_log('tempdir root has invalid permissions', testlog, 100)
-    end)
+    assert_log('tempdir root has invalid permissions', testlog, 100)
   end)
 
   it('too long', function()
diff --git a/test/functional/core/log_spec.lua b/test/functional/core/log_spec.lua
index 3b1ccd9559..f682df4155 100644
--- a/test/functional/core/log_spec.lua
+++ b/test/functional/core/log_spec.lua
@@ -6,7 +6,6 @@ local eq = helpers.eq
 local exec_lua = helpers.exec_lua
 local expect_exit = helpers.expect_exit
 local request = helpers.request
-local retry = helpers.retry
 
 describe('log', function()
   local testlog = 'Xtest_logging'
@@ -40,9 +39,7 @@ describe('log', function()
       }})
 
     local tid = _G._nvim_test_id
-    retry(nil, 1000, function()
-      assert_log(tid..'%.%d+%.%d +server_init:%d+: test log message', testlog, 100)
-    end)
+    assert_log(tid..'%.%d+%.%d +server_init:%d+: test log message', testlog, 100)
 
     exec_lua([[
       local j1 = vim.fn.jobstart({ vim.v.progpath, '-es', '-V1', '+foochild', '+qa!' }, vim.empty_dict())
@@ -50,8 +47,6 @@ describe('log', function()
     ]])
 
     -- Child Nvim spawned by jobstart() appends "/c" to parent name.
-    retry(nil, 1000, function()
-      assert_log('%.%d+%.%d/c +server_init:%d+: test log message', testlog, 100)
-    end)
+    assert_log('%.%d+%.%d/c +server_init:%d+: test log message', testlog, 100)
   end)
 end)
diff --git a/test/functional/core/startup_spec.lua b/test/functional/core/startup_spec.lua
index 9dabcd28b3..1be5de6488 100644
--- a/test/functional/core/startup_spec.lua
+++ b/test/functional/core/startup_spec.lua
@@ -43,10 +43,8 @@ describe('startup', function()
 
   it('--startuptime', function()
     clear({ args = {'--startuptime', testfile}})
-    retry(nil, 1000, function()
-      assert_log('sourcing', testfile, 100)
-      assert_log("require%('vim%._editor'%)", testfile, 100)
-    end)
+    assert_log('sourcing', testfile, 100)
+    assert_log("require%('vim%._editor'%)", testfile, 100)
   end)
 
   it('-D does not hang #12647', function()
diff --git a/test/functional/helpers.lua b/test/functional/helpers.lua
index 4e8bf1a323..6400db9f87 100644
--- a/test/functional/helpers.lua
+++ b/test/functional/helpers.lua
@@ -1,5 +1,4 @@
 require('coxpcall')
-local busted = require('busted')
 local luv = require('luv')
 local lfs = require('lfs')
 local mpack = require('mpack')
@@ -434,28 +433,6 @@ function module.connect(file_or_address)
   return Session.new(stream)
 end
 
--- Calls fn() until it succeeds, up to `max` times or until `max_ms`
--- milliseconds have passed.
-function module.retry(max, max_ms, fn)
-  assert(max == nil or max > 0)
-  assert(max_ms == nil or max_ms > 0)
-  local tries = 1
-  local timeout = (max_ms and max_ms or 10000)
-  local start_time = luv.now()
-  while true do
-    local status, result = pcall(fn)
-    if status then
-      return result
-    end
-    luv.update_time()  -- Update cached value of luv.now() (libuv: uv_now()).
-    if (max and tries >= max) or (luv.now() - start_time > timeout) then
-      busted.fail(string.format("retry() attempts: %d\n%s", tries, tostring(result)), 2)
-    end
-    tries = tries + 1
-    luv.sleep(20)  -- Avoid hot loop...
-  end
-end
-
 -- Starts a new global Nvim session.
 --
 -- Parameters are interpreted as startup args, OR a map with these keys:
diff --git a/test/functional/lua/vim_spec.lua b/test/functional/lua/vim_spec.lua
index 90eccc49c8..d90a78c92a 100644
--- a/test/functional/lua/vim_spec.lua
+++ b/test/functional/lua/vim_spec.lua
@@ -2,6 +2,7 @@
 local helpers = require('test.functional.helpers')(after_each)
 local Screen = require('test.functional.ui.screen')
 
+local nvim_prog = helpers.nvim_prog
 local funcs = helpers.funcs
 local meths = helpers.meths
 local command = helpers.command
@@ -22,7 +23,6 @@ local remove_trace = helpers.remove_trace
 local mkdir_p = helpers.mkdir_p
 local rmdir = helpers.rmdir
 local write_file = helpers.write_file
-local expect_exit = helpers.expect_exit
 local poke_eventloop = helpers.poke_eventloop
 local assert_alive = helpers.assert_alive
 
@@ -2910,9 +2910,14 @@ describe('lua: builtin modules', function()
   end)
 
 
-  it('does not work when disabled without runtime', function()
-    clear{args={'--luamod-dev'}, env={VIMRUNTIME='fixtures/a'}}
-    expect_exit(exec_lua, [[return vim.tbl_count {x=1,y=2}]])
+  it('fails when disabled without runtime', function()
+    clear()
+    command("let $VIMRUNTIME='fixtures/a'")
+    -- Use system([nvim,…]) instead of clear() to avoid stderr noise. #21844
+    local out = funcs.system({nvim_prog, '--clean', '--luamod-dev',
+      [[+call nvim_exec_lua('return vim.tbl_count {x=1,y=2}')]], '+qa!'}):gsub('\r\n', '\n')
+    eq(1, eval('v:shell_error'))
+    matches("'vim%.shared' not found", out)
   end)
 end)
 
diff --git a/test/functional/options/defaults_spec.lua b/test/functional/options/defaults_spec.lua
index c0d820f40e..6a28885bf0 100644
--- a/test/functional/options/defaults_spec.lua
+++ b/test/functional/options/defaults_spec.lua
@@ -3,6 +3,7 @@ local helpers = require('test.functional.helpers')(after_each)
 local Screen = require('test.functional.ui.screen')
 
 local assert_alive = helpers.assert_alive
+local assert_log = helpers.assert_log
 local meths = helpers.meths
 local command = helpers.command
 local clear = helpers.clear
@@ -20,6 +21,8 @@ local tbl_contains = helpers.tbl_contains
 local expect_exit = helpers.expect_exit
 local is_os = helpers.is_os
 
+local testlog = 'Xtest-defaults-log'
+
 describe('startup defaults', function()
   describe(':filetype', function()
     local function expect_filetype(expected)
@@ -275,6 +278,10 @@ describe('XDG defaults', function()
   -- Need separate describe() blocks to not run clear() twice.
   -- Do not put before_each() here for the same reasons.
 
+  after_each(function()
+    os.remove(testlog)
+  end)
+
   it("&runtimepath data-dir matches stdpath('data') #9910", function()
     clear()
     local rtp = eval('split(&runtimepath, ",")')
@@ -337,6 +344,7 @@ describe('XDG defaults', function()
       clear({
         args_rm={'runtimepath'},
         env={
+          NVIM_LOG_FILE=testlog,
           XDG_CONFIG_HOME=(root_path .. ('/x'):rep(4096)),
           XDG_CONFIG_DIRS=(root_path .. ('/a'):rep(2048)
                            .. env_sep.. root_path .. ('/b'):rep(2048)
@@ -351,6 +359,8 @@ describe('XDG defaults', function()
     end)
 
     it('are correctly set', function()
+      assert_log('Failed to start server: no such file or directory: /X/X/X', testlog, 10)
+
       local vimruntime, libdir = vimruntime_and_libdir()
 
       eq(((root_path .. ('/x'):rep(4096) .. '/nvim'
@@ -412,6 +422,7 @@ describe('XDG defaults', function()
       clear({
         args_rm={'runtimepath'},
         env={
+          NVIM_LOG_FILE=testlog,
           XDG_CONFIG_HOME='$XDG_DATA_HOME',
           XDG_CONFIG_DIRS='$XDG_DATA_DIRS',
           XDG_DATA_HOME='$XDG_CONFIG_HOME',
@@ -422,6 +433,8 @@ describe('XDG defaults', function()
     end)
 
     it('are not expanded', function()
+      assert_log('Failed to start server: no such file or directory: %$XDG_RUNTIME_DIR%/', testlog, 10)
+
       local vimruntime, libdir = vimruntime_and_libdir()
       eq((('$XDG_DATA_HOME/nvim'
           .. ',$XDG_DATA_DIRS/nvim'
diff --git a/test/functional/vimscript/server_spec.lua b/test/functional/vimscript/server_spec.lua
index 14c87d9d93..c89a0c4e93 100644
--- a/test/functional/vimscript/server_spec.lua
+++ b/test/functional/vimscript/server_spec.lua
@@ -1,4 +1,5 @@
 local helpers = require('test.functional.helpers')(after_each)
+local assert_log = helpers.assert_log
 local eq, neq, eval = helpers.eq, helpers.neq, helpers.eval
 local clear, funcs, meths = helpers.clear, helpers.funcs, helpers.meths
 local ok = helpers.ok
@@ -7,6 +8,8 @@ local pcall_err = helpers.pcall_err
 local mkdir = helpers.mkdir
 local is_os = helpers.is_os
 
+local testlog = 'Xtest-server-log'
+
 local function clear_serverlist()
   for _, server in pairs(funcs.serverlist()) do
     funcs.serverstop(server)
@@ -14,6 +17,10 @@ local function clear_serverlist()
 end
 
 describe('server', function()
+  after_each(function()
+    os.remove(testlog)
+  end)
+
   it('serverstart() stores sockets in $XDG_RUNTIME_DIR', function()
     local dir = 'Xtest_xdg_run'
     mkdir(dir)
@@ -74,13 +81,20 @@ describe('server', function()
   end)
 
   it('serverstop() returns false for invalid input', function()
-    clear()
+    clear{env={
+      NVIM_LOG_FILE=testlog,
+      NVIM_LISTEN_ADDRESS='.',
+    }}
     eq(0, eval("serverstop('')"))
     eq(0, eval("serverstop('bogus-socket-name')"))
+    assert_log('Not listening on bogus%-socket%-name', testlog, 10)
   end)
 
   it('parses endpoints', function()
-    clear()
+    clear{env={
+      NVIM_LOG_FILE=testlog,
+      NVIM_LISTEN_ADDRESS='.',
+    }}
     clear_serverlist()
     eq({}, funcs.serverlist())
 
@@ -104,6 +118,7 @@ describe('server', function()
     if status then
       table.insert(expected, v4)
       pcall(funcs.serverstart, v4)  -- exists already; ignore
+      assert_log('Failed to start server: address already in use: 127%.0%.0%.1', testlog, 10)
     end
 
     local v6 = '::1:12345'
@@ -111,6 +126,7 @@ describe('server', function()
     if status then
       table.insert(expected, v6)
       pcall(funcs.serverstart, v6)  -- exists already; ignore
+      assert_log('Failed to start server: address already in use: ::1', testlog, 10)
     end
     eq(expected, funcs.serverlist())
     clear_serverlist()
diff --git a/test/helpers.lua b/test/helpers.lua
index 3fe4322501..82ff23bef8 100644
--- a/test/helpers.lua
+++ b/test/helpers.lua
@@ -1,6 +1,7 @@
 require('test.compat')
 local shared = require('vim.shared')
 local assert = require('luassert')
+local busted = require('busted')
 local luv = require('luv')
 local lfs = require('lfs')
 local relpath = require('pl.path').relpath
@@ -45,6 +46,28 @@ function module.sleep(ms)
   luv.sleep(ms)
 end
 
+-- Calls fn() until it succeeds, up to `max` times or until `max_ms`
+-- milliseconds have passed.
+function module.retry(max, max_ms, fn)
+  assert(max == nil or max > 0)
+  assert(max_ms == nil or max_ms > 0)
+  local tries = 1
+  local timeout = (max_ms and max_ms or 10000)
+  local start_time = luv.now()
+  while true do
+    local status, result = pcall(fn)
+    if status then
+      return result
+    end
+    luv.update_time()  -- Update cached value of luv.now() (libuv: uv_now()).
+    if (max and tries >= max) or (luv.now() - start_time > timeout) then
+      busted.fail(string.format("retry() attempts: %d\n%s", tries, tostring(result)), 2)
+    end
+    tries = tries + 1
+    luv.sleep(20)  -- Avoid hot loop...
+  end
+end
+
 local check_logs_useless_lines = {
   ['Warning: noted but unhandled ioctl']=1,
   ['could cause spurious value errors to appear']=2,
@@ -87,6 +110,8 @@ end
 
 --- Asserts that `pat` matches (or *not* if inverse=true) any line in the tail of `logfile`.
 ---
+--- Retries for 1 second in case of filesystem delay.
+---
 ---@param pat (string) Lua pattern to match lines in the log file
 ---@param logfile (string) Full path to log file (default=$NVIM_LOG_FILE)
 ---@param nrlines (number) Search up to this many log lines
@@ -96,18 +121,21 @@ function module.assert_log(pat, logfile, nrlines, inverse)
   assert(logfile ~= nil, 'no logfile')
   nrlines = nrlines or 10
   inverse = inverse or false
-  local lines = module.read_file_list(logfile, -nrlines) or {}
-  local msg = string.format('Pattern %q %sfound in log (last %d lines): %s:\n%s',
-    pat, (inverse and '' or 'not '), nrlines, logfile, '    '..table.concat(lines, '\n    '))
-  for _,line in ipairs(lines) do
-    if line:match(pat) then
-      if inverse then error(msg) else return end
+
+  module.retry(nil, 1000, function()
+    local lines = module.read_file_list(logfile, -nrlines) or {}
+    local msg = string.format('Pattern %q %sfound in log (last %d lines): %s:\n%s',
+      pat, (inverse and '' or 'not '), nrlines, logfile, '    '..table.concat(lines, '\n    '))
+    for _,line in ipairs(lines) do
+      if line:match(pat) then
+        if inverse then error(msg) else return end
+      end
     end
-  end
-  if not inverse then error(msg) end
+    if not inverse then error(msg) end
+  end)
 end
 
---- Asserts that `pat` does NOT matche any line in the tail of `logfile`.
+--- Asserts that `pat` does NOT match any line in the tail of `logfile`.
 ---
 --- @see assert_log
 function module.assert_nolog(pat, logfile, nrlines)