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, 42 insertions, 18 deletions

diff --git a/src/nvim/api/vim.c b/src/nvim/api/vim.c
index 77b4900f4f..a60a069fae 100644
--- a/src/nvim/api/vim.c
+++ b/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;
 }
 
diff --git a/src/nvim/event/process.c b/src/nvim/event/process.c
index 653fffae1c..1ec11f1eb6 100644
--- a/src/nvim/event/process.c
+++ b/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;
 }
 
diff --git a/src/nvim/log.c b/src/nvim/log.c
index 6ff1aab9a0..bf8e2f9315 100644
--- a/src/nvim/log.c
+++ b/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,
-             (int)size - 1);
-  if (strequal("$" LOG_FILE_ENV, log_file_path)
+  expand_env((char_u *)"$" ENV_LOGFILE, (char_u *)log_file_path, (int)size - 1);
+  if (strequal("$" ENV_LOGFILE, 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",
-              log_levels[log_level], date_time, millis, pid,
+    ? fprintf(log_file, "%s %s.%03d %-10s %s",
+              log_levels[log_level], date_time, millis, name,
               (context == NULL ? "?:" : context))
-                               : fprintf(log_file, "%s %s.%03d %-5" PRId64 " %s%s:%d: ",
-                                         log_levels[log_level], date_time, millis, pid,
+                               : fprintf(log_file, "%s %s.%03d %-10s %s%s:%d: ",
+                                         log_levels[log_level], date_time, millis, name,
                                          (context == NULL ? "" : context),
                                          func_name, line_num);
   if (rv < 0) {
diff --git a/src/nvim/msgpack_rpc/server.c b/src/nvim/msgpack_rpc/server.c
index f15ce82917..3ced39117a 100644
--- a/src/nvim/msgpack_rpc/server.c
+++ b/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;
 }
 
diff --git a/src/nvim/os/os.h b/src/nvim/os/os.h
index bff2936f8e..a7496130cc 100644
--- a/src/nvim/os/os.h
+++ b/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
diff --git a/src/nvim/os/pty_process_unix.c b/src/nvim/os/pty_process_unix.c
index 4a49c0b162..c5d6af0ff6 100644
--- a/src/nvim/os/pty_process_unix.c
+++ b/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 || tcgetattr(tty_fd, &termios_default) != 0) {
+  if (tty_fd == -1) {
     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