feat(logging): include test-id in log messages

Problem:
1. Log messages (especially in CI) are hard to correlate with tests.
2. Since b353a5c05f02 #11886, dumplog() prints the logs next to test
   failures. This is noisy and gets in the way of the test results.

Solution:
1. Associate an incrementing id with each test and include it in log
   messages.
    - FUTURE: add v:name so Nvim instances can be formally "named"?
2. Mention "child" in log messages if the current Nvim is a child (based
   on the presence of $NVIM).

BEFORE:

    DBG … 12345      UI: event
    DBG … 12345      log_server_msg:722: RPC ->ch 1: …
    DBG … 12345      UI: flush
    DBG … 12345      inbuf_poll:444: blocking... events_enabled=1 events_pending=0
    DBG … 23454      UI: stop
    INF … 23454      os_exit:594: Nvim exit: 0

AFTER:

    DBG … T57        UI: event
    DBG … T57        log_server_msg:722: RPC ->ch 1: …
    DBG … T57        UI: flush
    DBG … T57        inbuf_poll:444: blocking... events_enabled=1 events_pending=0
    DBG … T57/child  UI: stop
    INF … T57/child  os_exit:594: Nvim exit: 0

9 files changed, 131 insertions, 56 deletions

diff --git a/test/README.md b/test/README.md
index cc630cb8bf..a6ce3c6d28 100644
--- a/test/README.md
+++ b/test/README.md
@@ -247,12 +247,17 @@ Number; !must be defined to function properly):
 
 - `BUSTED_ARGS` (F) (U): arguments forwarded to `busted`.
 
+- `CC` (U) (S): specifies which C compiler to use to preprocess files.
+  Currently only compilers with gcc-compatible arguments are supported.
+
 - `GDB` (F) (D): makes nvim instances to be run under `gdbserver`. It will be
   accessible on `localhost:7777`: use `gdb build/bin/nvim`, type `target remote
   :7777` inside.
 
 - `GDBSERVER_PORT` (F) (I): overrides port used for `GDB`.
 
+- `LOG_DIR` (FU) (S!): specifies where to seek for valgrind and ASAN log files.
+
 - `VALGRIND` (F) (D): makes nvim instances to be run under `valgrind`. Log
   files are named `valgrind-%p.log` in this case. Note that non-empty valgrind
   log may fail tests. Valgrind arguments may be seen in
@@ -269,11 +274,10 @@ Number; !must be defined to function properly):
 
 - `NVIM_LUA_NOTRACK` (F) (D): disable reference counting of Lua objects
 
-- `NVIM_PROG`, `NVIM_PRG` (F) (S): override path to Neovim executable (default
-  to `build/bin/nvim`).
+- `NVIM_PRG` (F) (S): path to Nvim executable (default: `build/bin/nvim`).
 
-- `CC` (U) (S): specifies which C compiler to use to preprocess files.
-  Currently only compilers with gcc-compatible arguments are supported.
+- `NVIM_TEST` (F) (S): Test id (example: "T1000") generated by the test runner
+  and prepended to `$NVIM_LOG_FILE` messages.
 
 - `NVIM_TEST_MAIN_CDEFS` (U) (1): makes `ffi.cdef` run in main process. This
   raises a possibility of bugs due to conflicts in header definitions, despite
@@ -295,8 +299,6 @@ Number; !must be defined to function properly):
 - `NVIM_TEST_RUN_FAILING_TESTS` (U) (1): makes `itp` run tests which are known
   to fail (marked by setting third argument to `true`).
 
-- `LOG_DIR` (FU) (S!): specifies where to seek for valgrind and ASAN log files.
-
 - `NVIM_TEST_CORE_*` (FU) (S): a set of environment variables which specify
   where to search for core files. Are supposed to be defined all at once.
 
diff --git a/test/busted/outputHandlers/nvim.lua b/test/busted/outputHandlers/nvim.lua
index 5e9c52e0bd..22b2f278ef 100644
--- a/test/busted/outputHandlers/nvim.lua
+++ b/test/busted/outputHandlers/nvim.lua
@@ -215,7 +215,9 @@ return function(options)
   end
 
   handler.testStart = function(element, _parent)
-    io.write(runString:format(handler.getFullName(element)))
+    local testid = _G._nvim_test_id or ''
+    local desc = ('%s %s'):format(testid, handler.getFullName(element))
+    io.write(runString:format(desc))
     io.flush()
 
     return nil, true
diff --git a/test/functional/api/keymap_spec.lua b/test/functional/api/keymap_spec.lua
index 4bee10a006..6bc6651e04 100644
--- a/test/functional/api/keymap_spec.lua
+++ b/test/functional/api/keymap_spec.lua
@@ -336,7 +336,7 @@ describe('nvim_get_keymap', function()
       return GlobalCount
     ]])
     local mapargs = meths.get_keymap('n')
-    assert.Truthy(type(mapargs[1].callback) == 'number', 'callback is not luaref number')
+    assert(type(mapargs[1].callback) == 'number', 'callback is not luaref number')
     mapargs[1].callback = nil
     eq({
       lhs='asdf',
@@ -815,7 +815,7 @@ describe('nvim_set_keymap, nvim_del_keymap', function()
     assert.truthy(string.match(funcs.maparg('asdf', 'n'),
                   "^<Lua function %d+>"))
     local mapargs = funcs.maparg('asdf', 'n', false, true)
-    assert.Truthy(type(mapargs.callback) == 'number', 'callback is not luaref number')
+    assert(type(mapargs.callback) == 'number', 'callback is not luaref number')
     mapargs.callback = nil
     eq(generate_mapargs('n', 'asdf', nil, {sid=sid_lua}), mapargs)
   end)
diff --git a/test/functional/core/log_spec.lua b/test/functional/core/log_spec.lua
new file mode 100644
index 0000000000..8553197305
--- /dev/null
+++ b/test/functional/core/log_spec.lua
@@ -0,0 +1,55 @@
+local helpers = require('test.functional.helpers')(after_each)
+local assert_log = helpers.assert_log
+local clear = helpers.clear
+local eq = helpers.eq
+local exec_lua = helpers.exec_lua
+local request = helpers.request
+local retry = helpers.retry
+local expect_exit = helpers.expect_exit
+
+describe('log', function()
+  local test_log_file = 'Xtest_logging'
+
+  after_each(function()
+    expect_exit('qa!')
+    os.remove(test_log_file)
+  end)
+
+  it('skipped before log_init', function()
+    -- This test is for _visibility_: adjust as needed, after checking for regression.
+    --
+    -- During startup some components may try to log before logging is setup.
+    -- That should be uncommon (ideally never)--and if there are MANY such
+    -- calls, that needs investigation.
+    clear()
+    eq(0, request('nvim__stats').log_skip)
+    clear{env={CDPATH='~doesnotexist'}}
+    assert(request('nvim__stats').log_skip <= 13)
+  end)
+
+  it('messages are formatted with name or test id', function()
+    -- Examples:
+    --    ERR 2022-05-29T12:30:03.800 T2         log_init:110: test log message
+    --    ERR 2022-05-29T12:30:03.814 T2/child   log_init:110: test log message
+
+    clear({env={
+      NVIM_LOG_FILE=test_log_file,
+      -- TODO: Can remove this after nvim_log #7062 is merged.
+      __NVIM_TEST_LOG='1'
+      }})
+
+    retry(nil, nil, function()
+      assert_log('T%d+\\.%d+\\.\\d +log_init:%d+: test log message', test_log_file, 100)
+    end)
+
+    exec_lua([[
+      local j1 = vim.fn.jobstart({ vim.v.progpath, '-es', '-V1', '+foochild', '+qa!' }, vim.empty_dict())
+      vim.fn.jobwait({ j1 }, 10000)
+    ]])
+
+    -- Child Nvim spawned by jobstart() appends "/child" to parent name.
+    retry(nil, nil, function()
+      assert_log('T%d+/child +log_init:%d+: test log message', test_log_file, 100)
+    end)
+  end)
+end)
diff --git a/test/functional/core/startup_spec.lua b/test/functional/core/startup_spec.lua
index 18d48efadc..919b7b3f9a 100644
--- a/test/functional/core/startup_spec.lua
+++ b/test/functional/core/startup_spec.lua
@@ -580,7 +580,7 @@ describe('user config init', function()
 
     it('loads default lua config, but shows an error', function()
       clear{ args_rm={'-u'}, env=xenv }
-      feed('<cr>') -- confirm "Conflicting config ..." message
+      feed('<cr><c-c>')  -- Dismiss "Conflicting config …" message.
       eq(1, eval('g:lua_rc'))
       matches('^E5422: Conflicting configs', meths.exec('messages', true))
     end)
@@ -632,13 +632,13 @@ describe('runtime:', function()
     eq(2, eval('g:lua_plugin'))
     -- Check if plugin_file_path is listed in :scriptname
     local scripts = meths.exec(':scriptnames', true)
-    assert.Truthy(scripts:find(plugin_file_path))
+    assert(scripts:find(plugin_file_path))
 
     -- Check if plugin_file_path is listed in startup profile
     local profile_reader = io.open(profiler_file, 'r')
     local profile_log = profile_reader:read('*a')
     profile_reader:close()
-    assert.Truthy(profile_log :find(plugin_file_path))
+    assert(profile_log:find(plugin_file_path))
 
     os.remove(profiler_file)
     rmdir(plugin_path)
diff --git a/test/functional/helpers.lua b/test/functional/helpers.lua
index ffb5694c15..0122229e77 100644
--- a/test/functional/helpers.lua
+++ b/test/functional/helpers.lua
@@ -433,16 +433,19 @@ function module.new_argv(...)
   table.insert(args, '--headless')
   local new_args
   local io_extra
-  local env = nil
+  local env = {}
   local opts = select(1, ...)
-  if type(opts) == 'table' then
+  if type(opts) ~= 'table' then
+    new_args = {...}
+  else
     args = remove_args(args, opts.args_rm)
     if opts.env then
-      local env_tbl = {}
+      opts.env['NVIM_TEST'] = nil
+      local env_opt = {}
       for k, v in pairs(opts.env) do
         assert(type(k) == 'string')
         assert(type(v) == 'string')
-        env_tbl[k] = v
+        env_opt[k] = v
       end
       for _, k in ipairs({
         'HOME',
@@ -458,23 +461,25 @@ function module.new_argv(...)
         'TMPDIR',
         'VIMRUNTIME',
       }) do
-        if not env_tbl[k] then
-          env_tbl[k] = os.getenv(k)
+        -- Set these from the environment only if not in opts.env.
+        if not env_opt[k] then
+          env_opt[k] = os.getenv(k)
         end
       end
-      env = {}
-      for k, v in pairs(env_tbl) do
+      for k, v in pairs(env_opt) do
         env[#env + 1] = k .. '=' .. v
       end
     end
     new_args = opts.args or {}
     io_extra = opts.io_extra
-  else
-    new_args = {...}
   end
   for _, arg in ipairs(new_args) do
     table.insert(args, arg)
   end
+
+  -- TODO(justinmk): introduce v:name and use that instead.
+  table.insert(env, ('NVIM_TEST=%s'):format(_G._nvim_test_id or '?'))
+
   return args, env, io_extra
 end
 
diff --git a/test/functional/preload.lua b/test/functional/preload.lua
index 24a3977e6b..74f03eaecf 100644
--- a/test/functional/preload.lua
+++ b/test/functional/preload.lua
@@ -1,8 +1,9 @@
--- Modules loaded here will not be cleared and reloaded by Busted.
+-- Modules loaded here will NOT be cleared and reloaded by Busted.
 -- Busted started doing this to help provide more isolation.  See issue #62
 -- for more information about this.
 local helpers = require('test.functional.helpers')(nil)
 local iswin = helpers.iswin
+local busted = require("busted")
 
 if iswin() then
   local ffi = require('ffi')
@@ -12,3 +13,28 @@ if iswin() then
   ]]
   ffi.C._set_fmode(0x8000)
 end
+
+local testid = (function()
+  local id = 0
+  return (function()
+    id = id + 1
+    return id
+  end)
+end)()
+
+-- Global before_each. https://github.com/Olivine-Labs/busted/issues/613
+local function before_each(_element, _parent)
+  local id = ('T%d'):format(testid())
+  _G._nvim_test_id = id
+  return nil, true
+end
+busted.subscribe({ 'test', 'start' },
+  before_each,
+  {
+    -- Ensure our --helper is handled before --output (see busted/runner.lua).
+    priority = 1,
+    -- Don't generate a test-id for skipped tests. /shrug
+    predicate = function (element, _, status)
+      return not ((element.descriptor == 'pending' or status == 'pending'))
+    end
+  })
diff --git a/test/functional/vimscript/let_spec.lua b/test/functional/vimscript/let_spec.lua
index 4ff4090a18..6e93655e32 100644
--- a/test/functional/vimscript/let_spec.lua
+++ b/test/functional/vimscript/let_spec.lua
@@ -47,33 +47,33 @@ describe(':let', function()
   end)
 
   it("multibyte env var #8398 #9267", function()
-    command("let $NVIM_TEST = 'AìaB'")
-    eq('AìaB', eval('$NVIM_TEST'))
-    command("let $NVIM_TEST = 'AaあB'")
-    eq('AaあB', eval('$NVIM_TEST'))
+    command("let $NVIM_TEST_LET = 'AìaB'")
+    eq('AìaB', eval('$NVIM_TEST_LET'))
+    command("let $NVIM_TEST_LET = 'AaあB'")
+    eq('AaあB', eval('$NVIM_TEST_LET'))
     local mbyte = [[\p* .ม .ม .ม .ม่ .ม่ .ม่ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ ֹֻ ֹֻ ֹֻ .ֹֻ .ֹֻ .ֹֻ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ a a a ca ca ca à à à]]
-    command("let $NVIM_TEST = '"..mbyte.."'")
-    eq(mbyte, eval('$NVIM_TEST'))
+    command("let $NVIM_TEST_LET = '"..mbyte.."'")
+    eq(mbyte, eval('$NVIM_TEST_LET'))
   end)
 
   it("multibyte env var to child process #8398 #9267",  function()
-    local cmd_get_child_env = "let g:env_from_child = system(['"..nvim_dir.."/printenv-test', 'NVIM_TEST'])"
-    command("let $NVIM_TEST = 'AìaB'")
+    local cmd_get_child_env = "let g:env_from_child = system(['"..nvim_dir.."/printenv-test', 'NVIM_TEST_LET'])"
+    command("let $NVIM_TEST_LET = 'AìaB'")
     command(cmd_get_child_env)
-    eq(eval('$NVIM_TEST'), eval('g:env_from_child'))
+    eq(eval('$NVIM_TEST_LET'), eval('g:env_from_child'))
 
-    command("let $NVIM_TEST = 'AaあB'")
+    command("let $NVIM_TEST_LET = 'AaあB'")
     command(cmd_get_child_env)
-    eq(eval('$NVIM_TEST'), eval('g:env_from_child'))
+    eq(eval('$NVIM_TEST_LET'), eval('g:env_from_child'))
 
     local mbyte = [[\p* .ม .ม .ม .ม่ .ม่ .ม่ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ ֹֻ ֹֻ ֹֻ .ֹֻ .ֹֻ .ֹֻ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ a a a ca ca ca à à à]]
-    command("let $NVIM_TEST = '"..mbyte.."'")
+    command("let $NVIM_TEST_LET = '"..mbyte.."'")
     command(cmd_get_child_env)
-    eq(eval('$NVIM_TEST'), eval('g:env_from_child'))
+    eq(eval('$NVIM_TEST_LET'), eval('g:env_from_child'))
   end)
 
   it("release of list assigned to l: variable does not trigger assertion #12387, #12430", function()
diff --git a/test/helpers.lua b/test/helpers.lua
index 7d2f8f760a..f37af9d08d 100644
--- a/test/helpers.lua
+++ b/test/helpers.lua
@@ -40,10 +40,6 @@ function module.popen_r(...)
   return io.popen(module.argss_to_cmd(...), 'r')
 end
 
-function module.popen_w(...)
-  return io.popen(module.argss_to_cmd(...), 'w')
-end
-
 -- sleeps the test runner (_not_ the nvim instance)
 function module.sleep(ms)
   luv.sleep(ms)
@@ -104,16 +100,16 @@ end
 ---
 ---@param pat string      Lua pattern to search for in the log file
 ---@param logfile string  Full path to log file (default=$NVIM_LOG_FILE)
-function module.assert_log(pat, logfile)
+---@param nrlines number  Search up to this many log lines
+function module.assert_log(pat, logfile, nrlines)
   logfile = logfile or os.getenv('NVIM_LOG_FILE') or '.nvimlog'
-  local nrlines = 10
+  nrlines = nrlines or 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))
+    pat, nrlines, logfile, '    '..table.concat(lines, '\n    ')))
 end
 
 -- Invokes `fn` and returns the error string (with truncated paths), or raises
@@ -271,7 +267,7 @@ module.uname = (function()
       return platform
     end
 
-    if os.getenv("SYSTEM_NAME") then  -- From CMAKE_SYSTEM_NAME.
+    if os.getenv("SYSTEM_NAME") then  -- From CMAKE_HOST_SYSTEM_NAME.
       platform = string.lower(os.getenv("SYSTEM_NAME"))
       return platform
     end
@@ -409,17 +405,6 @@ function module.check_cores(app, force)
   end
 end
 
-function module.which(exe)
-  local pipe = module.popen_r('which', exe)
-  local ret = pipe:read('*a')
-  pipe:close()
-  if ret == '' then
-    return nil
-  else
-    return ret:sub(1, -2)
-  end
-end
-
 function module.repeated_read_cmd(...)
   for _ = 1, 10 do
     local stream = module.popen_r(...)