1 files changed, 95 insertions, 79 deletions

diff --git a/src/nvim/log.c b/src/nvim/log.c
index 5539e3d6c5..57c7c4758b 100644
--- a/src/nvim/log.c
+++ b/src/nvim/log.c
@@ -16,16 +16,19 @@
 #include <uv.h>
 
 #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"
 
-#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 };
 
+static bool did_log_init = false;
 static uv_mutex_t mutex;
 
 #ifdef INCLUDE_GENERATED_DECLARATIONS
@@ -49,36 +52,29 @@ static bool log_try_create(char *fname)
   return true;
 }
 
-/// Initializes path to log file. Sets $NVIM_LOG_FILE if empty.
-///
-/// Tries $NVIM_LOG_FILE, or falls back to $XDG_CACHE_HOME/nvim/log. Path to log
-/// file is cached, so only the first call has effect, unless first call was not
-/// successful. Failed initialization indicates either a bug in expand_env()
-/// or both $NVIM_LOG_FILE and $HOME environment variables are undefined.
+/// Initializes the log file path and sets $NVIM_LOG_FILE if empty.
 ///
-/// @return true if path was initialized, false otherwise.
-static bool log_path_init(void)
+/// 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
+/// and $HOME environment variables are undefined.
+static void log_path_init(void)
 {
-  if (log_file_path[0]) {
-    return true;
-  }
   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)) {
-    // Make kXDGCacheHome if it does not exist.
-    char *cachehome = get_xdg_home(kXDGCacheHome);
+    // Make $XDG_STATE_HOME if it does not exist.
+    char *loghome = get_xdg_home(kXDGStateHome);
     char *failed_dir = NULL;
     bool log_dir_failure = false;
-    if (!os_isdir((char_u *)cachehome)) {
-      log_dir_failure = (os_mkdir_recurse(cachehome, 0700, &failed_dir) != 0);
+    if (!os_isdir((char_u *)loghome)) {
+      log_dir_failure = (os_mkdir_recurse(loghome, 0700, &failed_dir) != 0);
     }
-    XFREE_CLEAR(cachehome);
+    XFREE_CLEAR(loghome);
     // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
-    char *defaultpath = stdpaths_user_cache_subpath("log");
+    char *defaultpath = stdpaths_user_state_subpath("log", 0, true);
     size_t len = xstrlcpy(log_file_path, defaultpath, size);
     xfree(defaultpath);
     // Fall back to .nvimlog
@@ -88,22 +84,23 @@ static bool log_path_init(void)
     // Fall back to stderr
     if (len >= size || !log_try_create(log_file_path)) {
       log_file_path[0] = '\0';
-      return false;
+      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));
     }
     XFREE_CLEAR(failed_dir);
   }
-  return true;
 }
 
 void log_init(void)
 {
-  uv_mutex_init(&mutex);
+  uv_mutex_init_recursive(&mutex);
+  // AFTER init_homedir ("~", XDG) and set_init_1 (env vars). 22b52dd462e5 #11501
   log_path_init();
+  did_log_init = true;
 }
 
 void log_lock(void)
@@ -124,10 +121,20 @@ void log_unlock(void)
 /// @param line_num   Source line number, or -1
 /// @param eol        Append linefeed "\n"
 /// @param fmt        printf-style format string
+///
+/// @return true if log was emitted normally, false if failed or recursive
 bool logmsg(int log_level, const char *context, const char *func_name, int line_num, bool eol,
             const char *fmt, ...)
   FUNC_ATTR_UNUSED FUNC_ATTR_PRINTF(6, 7)
 {
+  static bool recursive = false;
+  static bool did_msg = false;  // Showed recursion message?
+  if (!did_log_init) {
+    g_stats.log_skip++;
+    // set_init_1 may try logging before we are ready. 6f27f5ef91b3 #10183
+    return false;
+  }
+
   if (log_level < MIN_LOG_LEVEL) {
     return false;
   }
@@ -139,13 +146,19 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
 #endif
 
   log_lock();
+  if (recursive) {
+    if (!did_msg) {
+      did_msg = true;
+      msg_schedule_semsg("E5430: %s:%d: recursive log!", func_name ? func_name : context, line_num);
+    }
+    g_stats.log_skip++;
+    log_unlock();
+    return false;
+  }
+  recursive = true;
   bool ret = false;
   FILE *log_file = open_log_file();
 
-  if (log_file == NULL) {
-    goto end;
-  }
-
   va_list args;
   va_start(args, fmt);
   ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num,
@@ -155,7 +168,8 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
   if (log_file != stderr && log_file != stdout) {
     fclose(log_file);
   }
-end:
+
+  recursive = false;
   log_unlock();
   return ret;
 }
@@ -166,51 +180,36 @@ void log_uv_handles(void *loop)
   log_lock();
   FILE *log_file = open_log_file();
 
-  if (log_file == NULL) {
-    goto end;
-  }
-
   uv_print_all_handles(l, log_file);
 
   if (log_file != stderr && log_file != stdout) {
     fclose(log_file);
   }
-end:
+
   log_unlock();
 }
 
 /// Open the log file for appending.
 ///
-/// @return FILE* decided by log_path_init() or stderr in case of error
+/// @return Log file, or stderr on failure
 FILE *open_log_file(void)
 {
-  static bool opening_log_file = false;
-  // Disallow recursion. (This only matters for log_path_init; for logmsg and
-  // friends we use a mutex: log_lock).
-  if (opening_log_file) {
-    do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true,
-                   "Cannot LOG() recursively.");
-    return stderr;
-  }
-
-  FILE *log_file = NULL;
-  opening_log_file = true;
-  if (log_path_init()) {
-    log_file = fopen(log_file_path, "a");
-  }
-  opening_log_file = false;
-
-  if (log_file != NULL) {
-    return log_file;
+  errno = 0;
+  if (log_file_path[0]) {
+    FILE *f = fopen(log_file_path, "a");
+    if (f != NULL) {
+      return f;
+    }
   }
 
   // May happen if:
-  //  - LOG() is called before early_init()
+  //  - fopen() failed
+  //  - LOG() is called before log_init()
   //  - Directory does not exist
   //  - File is not writable
-  do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true,
-                 "Logging to stderr, failed to open $" LOG_FILE_ENV ": %s",
-                 log_file_path);
+  do_log_to_file(stderr, LOGLVL_ERR, NULL, __func__, __LINE__, true,
+                 "failed to open $" ENV_LOGFILE " (%s): %s",
+                 strerror(errno), log_file_path);
   return stderr;
 }
 
@@ -237,8 +236,7 @@ void log_callstack_to_file(FILE *log_file, const char *const func_name, const in
   // Now we have a command string like:
   //    addr2line -e /path/to/exe -f -p 0x123 0x456 ...
 
-  do_log_to_file(log_file, DEBUG_LOG_LEVEL, NULL, func_name, line_num, true,
-                 "trace:");
+  do_log_to_file(log_file, LOGLVL_DBG, NULL, func_name, line_num, true, "trace:");
   FILE *fp = popen(cmdbuf, "r");
   char linebuf[IOSIZE];
   while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) {
@@ -255,13 +253,7 @@ void log_callstack(const char *const func_name, const int line_num)
 {
   log_lock();
   FILE *log_file = open_log_file();
-  if (log_file == NULL) {
-    goto end;
-  }
-
   log_callstack_to_file(log_file, func_name, line_num);
-
-end:
   log_unlock();
 }
 #endif
@@ -282,14 +274,18 @@ static bool do_log_to_file(FILE *log_file, int log_level, const char *context,
 static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
                              const char *func_name, int line_num, bool eol, const char *fmt,
                              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[] = {
-    [DEBUG_LOG_LEVEL]   = "DEBUG",
-    [INFO_LOG_LEVEL]    = "INFO ",
-    [WARN_LOG_LEVEL]    = "WARN ",
-    [ERROR_LOG_LEVEL]   = "ERROR",
+    [LOGLVL_DBG] = "DBG",
+    [LOGLVL_INF] = "INF",
+    [LOGLVL_WRN] = "WRN",
+    [LOGLVL_ERR] = "ERR",
   };
-  assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL);
+  assert(log_level >= LOGLVL_DBG && log_level <= LOGLVL_ERR);
 
   // Format the timestamp.
   struct tm local_time;
@@ -297,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;
   }
 
@@ -308,16 +303,37 @@ 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.
+  // TODO(justinmk): expose this as v:name ?
+  if (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[0] != NUL) {
+      snprintf(name, sizeof(name), "%s", serv);
+    } else {
+      int64_t pid = os_get_pid();
+      snprintf(name, sizeof(name), "?.%-5" PRId64, pid);
+    }
+  }
+
   // 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 (name[0] == '?') {
+    // No v:servername yet. Clear `name` so that the next log can try again.
+    name[0] = '\0';
+  }
+
   if (rv < 0) {
     return false;
   }