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

6 files changed, 115 insertions, 29 deletions

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