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

Problem:
1. Log messages (especially in CI) are hard to correlate with tests.
2. Since b353a5c05f #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

src/nvim/api/vim.c

@@ -1790,8 +1790,9 @@ Dictionary nvim__stats(void)
 {
   Dictionary rv = ARRAY_DICT_INIT;
   PUT(rv, "fsync", INTEGER_OBJ(g_stats.fsync));
-  PUT(rv, "redraw", INTEGER_OBJ(g_stats.redraw));
+  PUT(rv, "log_skip", INTEGER_OBJ(g_stats.log_skip));
   PUT(rv, "lua_refcount", INTEGER_OBJ(nlua_get_global_ref_count()));
+  PUT(rv, "redraw", INTEGER_OBJ(g_stats.redraw));
   return rv;
 }
 

src/nvim/event/process.c

@@ -120,7 +120,7 @@ int process_spawn(Process *proc, bool in, bool out, bool err)
   proc->internal_close_cb = decref;
   proc->refcount++;
   kl_push(WatcherPtr, proc->loop->children, proc);
-  DLOG("new: pid=%d argv=[%s]", proc->pid, *proc->argv);
+  DLOG("new: pid=%d argv=[%s]", proc->pid, proc->argv[0]);
   return 0;
 }
 

src/nvim/log.c

@@ -23,8 +23,6 @@
 #include "nvim/os/time.h"
 #include "nvim/types.h"
 
-#define LOG_FILE_ENV "NVIM_LOG_FILE"
-
 /// Cached location of the expanded log file path decided by log_path_init().
 static char log_file_path[MAXPATHL + 1] = { 0 };
 
@@ -52,7 +50,7 @@ static bool log_try_create(char *fname)
   return true;
 }
 
-/// Initializes path to log file. Sets $NVIM_LOG_FILE if empty.
+/// Initializes the log file path and sets $NVIM_LOG_FILE if empty.
 ///
 /// Tries $NVIM_LOG_FILE, or falls back to $XDG_STATE_HOME/nvim/log. Failed
 /// initialization indicates either a bug in expand_env() or both $NVIM_LOG_FILE
@@ -60,9 +58,8 @@ static bool log_try_create(char *fname)
 static void log_path_init(void)
 {
   size_t size = sizeof(log_file_path);
-  expand_env((char_u *)"$" LOG_FILE_ENV, (char_u *)log_file_path,
+  expand_env((char_u *)"$" ENV_LOGFILE, (char_u *)log_file_path, (int)size - 1);
-             (int)size - 1);
+  if (strequal("$" ENV_LOGFILE, log_file_path)
-  if (strequal("$" LOG_FILE_ENV, log_file_path)
       || log_file_path[0] == '\0'
       || os_isdir((char_u *)log_file_path)
       || !log_try_create(log_file_path)) {
@@ -87,7 +84,7 @@ static void log_path_init(void)
       log_file_path[0] = '\0';
       return;
     }
-    os_setenv(LOG_FILE_ENV, log_file_path, true);
+    os_setenv(ENV_LOGFILE, log_file_path, true);
     if (log_dir_failure) {
       WLOG("Failed to create directory %s for writing logs: %s",
            failed_dir, os_strerror(log_dir_failure));
@@ -209,7 +206,7 @@ FILE *open_log_file(void)
   //  - Directory does not exist
   //  - File is not writable
   do_log_to_file(stderr, LOGLVL_ERR, NULL, __func__, __LINE__, true,
-                 "failed to open $" LOG_FILE_ENV " (%s): %s",
+                 "failed to open $" ENV_LOGFILE " (%s): %s",
                  strerror(errno), log_file_path);
   return stderr;
 }
@@ -277,6 +274,9 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
                              va_list args)
   FUNC_ATTR_PRINTF(7, 0)
 {
+  // Name of the Nvim instance that produced the log.
+  static char name[16] = { 0 };
+
   static const char *log_levels[] = {
     [LOGLVL_DBG] = "DBG",
     [LOGLVL_INF] = "INF",
@@ -302,14 +302,25 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
     millis = (int)curtime.tv_usec / 1000;
   }
 
+  // Get a name for this Nvim instance.
+  if (name[0] == '\0') {
+    const char *testid = os_getenv("NVIM_TEST");
+    const char *parent = os_getenv(ENV_NVIM);
+    if (testid) {
+      snprintf(name, sizeof(name), "%s%s", testid ? testid : "", parent ? "/child" : "");
+    } else {
+      int64_t pid = os_get_pid();
+      snprintf(name, sizeof(name), "%-5" PRId64 "%s", pid, parent ? "/child" : "");
+    }
+  }
+
   // Print the log message.
-  int64_t pid = os_get_pid();
   int rv = (line_num == -1 || func_name == NULL)
-    ? fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s",
+    ? fprintf(log_file, "%s %s.%03d %-10s %s",
-              log_levels[log_level], date_time, millis, pid,
+              log_levels[log_level], date_time, millis, name,
               (context == NULL ? "?:" : context))
-                               : fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s%s:%d: ",
+                               : fprintf(log_file, "%s %s.%03d %-10s %s%s:%d: ",
-                                         log_levels[log_level], date_time, millis, pid,
+                                         log_levels[log_level], date_time, millis, name,
                                          (context == NULL ? "" : context),
                                          func_name, line_num);
   if (rv < 0) {

src/nvim/msgpack_rpc/server.c

@@ -23,7 +23,6 @@
 
 #define MAX_CONNECTIONS 32
 #define ENV_LISTEN "NVIM_LISTEN_ADDRESS"  // deprecated
-#define ENV_NVIM "NVIM"
 
 static garray_T watchers = GA_EMPTY_INIT_VALUE;
 
@@ -56,6 +55,11 @@ bool server_init(const char *listen_addr)
     os_unsetenv(ENV_LISTEN);
   }
 
+  // TODO: this is for logging_spec. Can remove this after nvim_log #7062 is merged.
+  if (os_env_exists("__NVIM_TEST_LOG")) {
+    ELOG("test log message");
+  }
+
   return rv == 0;
 }
 

src/nvim/os/os.h

@@ -16,4 +16,7 @@
 # include "os/users.h.generated.h"
 #endif
 
+#define ENV_LOGFILE "NVIM_LOG_FILE"
+#define ENV_NVIM "NVIM"
+
 #endif  // NVIM_OS_OS_H

src/nvim/os/pty_process_unix.c

@@ -163,10 +163,15 @@ static struct termios termios_default;
 /// @param tty_fd   TTY file descriptor, or -1 if not in a terminal.
 void pty_process_save_termios(int tty_fd)
 {
-  DLOG("tty_fd=%d", tty_fd);
+  if (tty_fd == -1) {
-  if (tty_fd == -1 || tcgetattr(tty_fd, &termios_default) != 0) {
     return;
   }
+  int rv = tcgetattr(tty_fd, &termios_default);
+  if (rv != 0) {
+    ELOG("tcgetattr failed (tty_fd=%d): %s", tty_fd, strerror(errno));
+  } else {
+    DLOG("tty_fd=%d", tty_fd);
+  }
 }
 
 /// @returns zero on success, or negative error code

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
+- `NVIM_PRG` (F) (S): path to Nvim executable (default: `build/bin/nvim`).
-  to `build/bin/nvim`).
 
-- `CC` (U) (S): specifies which C compiler to use to preprocess files.
+- `NVIM_TEST` (F) (S): Test id (example: "T1000") generated by the test runner
-  Currently only compilers with gcc-compatible arguments are supported.
+  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.
 

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

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)

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)

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)

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
+        -- Set these from the environment only if not in opts.env.
-          env_tbl[k] = os.getenv(k)
+        if not env_opt[k] then
+          env_opt[k] = os.getenv(k)
         end
       end
-      env = {}
+      for k, v in pairs(env_opt) do
-      for k, v in pairs(env_tbl) 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
 

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
+  })

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'")
+    command("let $NVIM_TEST_LET = 'AìaB'")
-    eq('AìaB', eval('$NVIM_TEST'))
+    eq('AìaB', eval('$NVIM_TEST_LET'))
-    command("let $NVIM_TEST = 'AaあB'")
+    command("let $NVIM_TEST_LET = 'AaあB'")
-    eq('AaあB', eval('$NVIM_TEST'))
+    eq('AaあB', eval('$NVIM_TEST_LET'))
     local mbyte = [[\p* .ม .ม .ม .ม่ .ม่ .ม่ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ ֹֻ ֹֻ ֹֻ .ֹֻ .ֹֻ .ֹֻ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹ ֹ ֹ .ֹ .ֹ .ֹ ֹֻ ֹֻ
                     .ֹֻ .ֹֻ .ֹֻ a a a ca ca ca à à à]]
-    command("let $NVIM_TEST = '"..mbyte.."'")
+    command("let $NVIM_TEST_LET = '"..mbyte.."'")
-    eq(mbyte, eval('$NVIM_TEST'))
+    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'])"
+    local cmd_get_child_env = "let g:env_from_child = system(['"..nvim_dir.."/printenv-test', 'NVIM_TEST_LET'])"
-    command("let $NVIM_TEST = 'AìaB'")
+    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()

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