test: avoid noise in NVIM_LOG_FILE

Problem:
Tests that _intentionally_ fail certain conditions cause noise in
$NVIM_LOG_FILE:

    $NVIM_LOG_FILE: /home/runner/work/neovim/neovim/build/.nvimlog
    (last 100 lines)
    WRN 2023-01-16T18:26:27.673 T599.7799.0 unsubscribe:519: RPC: ch 1: tried to unsubscribe unknown event 'doesnotexist'
    WRN 2023-01-16T18:29:00.557 ?.11151    server_start:163: Failed to start server: no such file or directory: /X/X/X/...
    WRN 2023-01-16T18:33:07.269 127.0.0.1:12345 server_start:163: Failed to start server: address already in use: 127.0.0.1
    ...
    -- Output to stderr:
    module 'vim.shared' not found:
    	no field package.preload['vim.shared']
    	no file './vim/shared.lua'
    	no file '/home/runner/nvim-deps/usr/share/lua/5.1/vim/shared.lua'
    	no file '/home/runner/nvim-deps/usr/share/lua/5.1/vim/shared/init.lua'
    	no file '/home/runner/nvim-deps/usr/lib/lua/5.1/vim/shared.lua'
    	no file '/home/runner/nvim-deps/usr/lib/lua/5.1/vim/shared/init.lua'
    	no file './vim/shared.so'
    	...
    E970: Failed to initialize builtin lua modules

Solution:
- Log to a private $NVIM_LOG_FILE in tests that intentionally fail and
  cause ERR log messages.
- Assert that the expected messages are actually logged.

5 files changed, 65 insertions, 7 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..1ee2e5a517 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,14 @@ describe('notify', function()
   end)
 
   it('unsubscribe non-existing event #8745', function()
+    clear{env={
+      NVIM_LOG_FILE=testlog,
+    }}
     nvim('subscribe', 'event1')
     nvim('unsubscribe', 'doesnotexist')
+    retry(nil, 1000, function()
+      assert_log("tried to unsubscribe unknown event 'doesnotexist'", testlog, 10)
+    end)
     nvim('unsubscribe', 'event1')
     assert_alive()
   end)
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..92b385c3b5 100644
--- a/test/functional/options/defaults_spec.lua
+++ b/test/functional/options/defaults_spec.lua
@@ -3,6 +3,8 @@ 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 retry = helpers.retry
 local meths = helpers.meths
 local command = helpers.command
 local clear = helpers.clear
@@ -20,6 +22,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 +279,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 +345,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 +360,10 @@ describe('XDG defaults', function()
     end)
 
     it('are correctly set', function()
+      retry(nil, 1000, function()
+        assert_log('Failed to start server: no such file or directory: /X/X/X', testlog, 10)
+      end)
+
       local vimruntime, libdir = vimruntime_and_libdir()
 
       eq(((root_path .. ('/x'):rep(4096) .. '/nvim'
@@ -412,6 +425,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 +436,9 @@ describe('XDG defaults', function()
     end)
 
     it('are not expanded', function()
+      retry(nil, 1000, function()
+        assert_log('Failed to start server: no such file or directory: %$XDG_RUNTIME_DIR%/', testlog, 10)
+      end)
       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..a2d99c7d45 100644
--- a/test/functional/vimscript/server_spec.lua
+++ b/test/functional/vimscript/server_spec.lua
@@ -1,4 +1,6 @@
 local helpers = require('test.functional.helpers')(after_each)
+local assert_log = helpers.assert_log
+local retry = helpers.retry
 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 +9,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 +18,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 +82,22 @@ 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')"))
+    retry(nil, 1000, function()
+      assert_log('Not listening on bogus%-socket%-name', testlog, 10)
+    end)
   end)
 
   it('parses endpoints', function()
-    clear()
+    clear{env={
+      NVIM_LOG_FILE=testlog,
+      NVIM_LISTEN_ADDRESS='.',
+    }}
     clear_serverlist()
     eq({}, funcs.serverlist())
 
@@ -104,6 +121,9 @@ describe('server', function()
     if status then
       table.insert(expected, v4)
       pcall(funcs.serverstart, v4)  -- exists already; ignore
+      retry(nil, 1000, function()
+        assert_log('Failed to start server: address already in use: 127%.0%.0%.1', testlog, 10)
+      end)
     end
 
     local v6 = '::1:12345'
@@ -111,6 +131,9 @@ describe('server', function()
     if status then
       table.insert(expected, v6)
       pcall(funcs.serverstart, v6)  -- exists already; ignore
+      retry(nil, 1000, function()
+        assert_log('Failed to start server: address already in use: ::1', testlog, 10)
+      end)
     end
     eq(expected, funcs.serverlist())
     clear_serverlist()