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/api/vim.c | 3 ++- src/nvim/event/process.c | 2 +- src/nvim/log.c | 37 ++++++++++++++++++++++++------------- src/nvim/msgpack_rpc/server.c | 6 +++++- src/nvim/os/os.h | 3 +++ src/nvim/os/pty_process_unix.c | 9 +++++++-- 6 files changed, 42 insertions(+), 18 deletions(-) (limited to 'src') 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 -- 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/eval/funcs.c | 2 +- src/nvim/log.c | 22 ++++++++------ src/nvim/msgpack_rpc/server.c | 67 ++++++++++++++++++++++--------------------- src/nvim/path.c | 7 ++++- 4 files changed, 56 insertions(+), 42 deletions(-) (limited to 'src') diff --git a/src/nvim/eval/funcs.c b/src/nvim/eval/funcs.c index 25f80758d2..2225076a0a 100644 --- a/src/nvim/eval/funcs.c +++ b/src/nvim/eval/funcs.c @@ -8497,7 +8497,7 @@ static void f_serverstart(typval_T *argvars, typval_T *rettv, FunPtr fptr) address = xstrdup(tv_get_string(argvars)); } } else { - address = server_address_new(); + address = server_address_new(NULL); } int result = server_start(address); 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); } } diff --git a/src/nvim/msgpack_rpc/server.c b/src/nvim/msgpack_rpc/server.c index 3ced39117a..c9e707aa92 100644 --- a/src/nvim/msgpack_rpc/server.c +++ b/src/nvim/msgpack_rpc/server.c @@ -42,7 +42,7 @@ bool server_init(const char *listen_addr) int rv = listen_addr ? server_start(listen_addr) : 1; if (0 != rv) { - listen_addr = server_address_new(); + listen_addr = server_address_new(NULL); if (!listen_addr) { return false; } @@ -55,7 +55,7 @@ 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. + // TODO(justinmk): 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"); } @@ -87,23 +87,26 @@ void server_teardown(void) /// Generates unique address for local server. /// -/// In Windows this is a named pipe in the format -/// \\.\pipe\nvim--. -/// -/// For other systems it is a path returned by vim_tempname(). -/// -/// This function is NOT thread safe -char *server_address_new(void) +/// Named pipe format: +/// - Windows: "\\.\pipe\.." +/// - Other: "~/.local/state/nvim/.." +char *server_address_new(const char *name) { -#ifdef WIN32 static uint32_t count = 0; - char template[ADDRESS_MAX_SIZE]; - snprintf(template, ADDRESS_MAX_SIZE, - "\\\\.\\pipe\\nvim-%" PRIu64 "-%" PRIu32, os_get_pid(), count++); - return xstrdup(template); + char fmt[ADDRESS_MAX_SIZE]; +#ifdef WIN32 + int r = snprintf(fmt, sizeof(fmt), "\\\\.\\pipe\\%s.%" PRIu64 ".%" PRIu32, + name ? name : "nvim", os_get_pid(), count++); #else - return (char *)vim_tempname(); + char *dir = get_xdg_home(kXDGStateHome); + int r = snprintf(fmt, sizeof(fmt), "%s/%s.%" PRIu64 ".%" PRIu32, + dir, name ? name : "nvim", os_get_pid(), count++); + xfree(dir); #endif + if ((size_t)r >= sizeof(fmt)) { + ELOG("truncated server address"); + } + return xstrdup(fmt); } /// Check if this instance owns a pipe address. @@ -118,35 +121,35 @@ bool server_owns_pipe_address(const char *path) return false; } -/// Starts listening for API calls. -/// -/// The socket type is determined by parsing `endpoint`: If it's a valid IPv4 -/// or IPv6 address in 'ip:[port]' format, then it will be a TCP socket. -/// Otherwise it will be a Unix socket or named pipe (Windows). +/// Starts listening for RPC calls. /// -/// If no port is given, a random one will be assigned. +/// Socket type is decided by the format of `addr`: +/// - TCP socket if it looks like an IPv4/6 address ("ip:[port]"). +/// - If [port] is omitted, a random one is assigned. +/// - Unix socket (or named pipe on Windows) otherwise. +/// - If the name doesn't contain slashes it is appended to a generated path. #8519 /// -/// @param endpoint Address of the server. Either a 'ip:[port]' string or an -/// arbitrary identifier (trimmed to 256 bytes) for the Unix -/// socket or named pipe. -/// @returns 0: success, 1: validation error, 2: already listening, -/// -errno: failed to bind or listen. -int server_start(const char *endpoint) +/// @param addr Server address: a "ip:[port]" string or arbitrary name or filepath (max 256 bytes) +/// for the Unix socket or named pipe. +/// @returns 0: success, 1: validation error, 2: already listening, -errno: failed to bind/listen. +int server_start(const char *addr) { - if (endpoint == NULL || endpoint[0] == '\0') { - WLOG("Empty or NULL endpoint"); + if (addr == NULL || addr[0] == '\0') { + WLOG("Empty or NULL address"); return 1; } + bool isname = !strstr(addr, ":") && !strstr(addr, "/") && !strstr(addr, "\\"); + char *addr_gen = isname ? server_address_new(addr) : NULL; SocketWatcher *watcher = xmalloc(sizeof(SocketWatcher)); - - int result = socket_watcher_init(&main_loop, watcher, endpoint); + int result = socket_watcher_init(&main_loop, watcher, isname ? addr_gen : addr); + xfree(addr_gen); if (result < 0) { xfree(watcher); return result; } - // Check if a watcher for the endpoint already exists + // Check if a watcher for the address already exists. for (int i = 0; i < watchers.ga_len; i++) { if (!strcmp(watcher->addr, ((SocketWatcher **)watchers.ga_data)[i]->addr)) { ELOG("Already listening on %s", watcher->addr); diff --git a/src/nvim/path.c b/src/nvim/path.c index 7f47ce083d..9859ca7daa 100644 --- a/src/nvim/path.c +++ b/src/nvim/path.c @@ -88,7 +88,12 @@ FileComparison path_full_compare(char_u *const s1, char_u *const s2, const bool return kDifferentFiles; } -/// Gets the tail (i.e., the filename segment) of a path `fname`. +/// Gets the tail (filename segment) of path `fname`. +/// +/// Examples: +/// - "dir/file.txt" => "file.txt" +/// - "file.txt" => "file.txt" +/// - "dir/" => "" /// /// @return pointer just past the last path separator (empty string, if fname /// ends in a slash), or empty string if fname is NULL. -- cgit