From 8f065205946844d87f00d6c55517521e3809f821 Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Mon, 23 May 2022 21:44:15 -0700 Subject: feat(logging): include test-id in log messages MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- src/nvim/log.c | 37 ++++++++++++++++++++++++------------- 1 file changed, 24 insertions(+), 13 deletions(-) (limited to 'src/nvim/log.c') 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) { -- cgit From 1f2c2a35ad14cfac002d87073471bd84a52860bf Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Wed, 1 Jun 2022 11:28:14 -0700 Subject: feat(server): instance "name", store pipes in stdpath(state) Problem: - Unix sockets are created in random /tmp dirs. - /tmp is messy, unclear when OSes actually clear it. - The generated paths are very ugly. This adds friction to reasoning about which paths belong to which Nvim instances. - No way to provide a human-friendly way to identify Nvim instances in logs or server addresses. Solution: - Store unix sockets in stdpath('state') - Allow --listen "name" and serverstart("name") to given a name (which is appended to a generated path). TODO: - is stdpath(state) the right place? --- src/nvim/log.c | 22 ++++++++++++++-------- 1 file changed, 14 insertions(+), 8 deletions(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index bf8e2f9315..d2c7782e5d 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -16,11 +16,13 @@ #include #include "auto/config.h" +#include "nvim/eval.h" #include "nvim/log.h" #include "nvim/main.h" #include "nvim/message.h" #include "nvim/os/os.h" #include "nvim/os/time.h" +#include "nvim/path.h" #include "nvim/types.h" /// Cached location of the expanded log file path decided by log_path_init(). @@ -291,8 +293,7 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context, return false; } char date_time[20]; - if (strftime(date_time, sizeof(date_time), "%Y-%m-%dT%H:%M:%S", - &local_time) == 0) { + if (strftime(date_time, sizeof(date_time), "%Y-%m-%dT%H:%M:%S", &local_time) == 0) { return false; } @@ -303,14 +304,19 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context, } // 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" : ""); + // TODO(justinmk): expose this as v:name ? + if (starting || name[0] == '\0') { + // Parent servername. + const char *parent = path_tail(os_getenv(ENV_NVIM)); + // Servername. Empty until starting=false. + const char *serv = path_tail(get_vim_var_str(VV_SEND_SERVER)); + if (parent && parent[0] != NUL) { + snprintf(name, sizeof(name), "%s/c", parent); // "/c" indicates child. + } else if (serv && serv[0] != NUL) { + snprintf(name, sizeof(name), "%s", serv ? serv : ""); } else { int64_t pid = os_get_pid(); - snprintf(name, sizeof(name), "%-5" PRId64 "%s", pid, parent ? "/child" : ""); + snprintf(name, sizeof(name), "?.%-5" PRId64, pid); } } -- cgit