fix(logging): skip recursion, fix crash #18764

Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd462e5 (#11501) regressed 6f27f5ef91b3 (#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initialized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used for RPC.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion, show "internal error" message.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.

1 files changed, 47 insertions, 19 deletions

diff --git a/src/nvim/log.c b/src/nvim/log.c
index 815d53b570..c0a73a00fd 100644
--- a/src/nvim/log.c
+++ b/src/nvim/log.c
@@ -17,6 +17,8 @@
 
 #include "auto/config.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/types.h"
@@ -26,6 +28,7 @@
 /// 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
@@ -103,7 +106,9 @@ static bool log_path_init(void)
 void log_init(void)
 {
   uv_mutex_init(&mutex);
+  // AFTER init_homedir ("~", XDG) and set_init_1 (env vars). 22b52dd462e5 #11501
   log_path_init();
+  did_log_init = true;
 }
 
 void log_lock(void)
@@ -116,6 +121,14 @@ void log_unlock(void)
   uv_mutex_unlock(&mutex);
 }
 
+static void on_log_recursive_event(void **argv)
+{
+  char *fn_name = argv[0];
+  ptrdiff_t linenr = (ptrdiff_t)argv[1];
+  siemsg("E5430: %s:%d: recursive log!", fn_name, linenr);
+  xfree(fn_name);
+}
+
 /// Logs a message to $NVIM_LOG_FILE.
 ///
 /// @param log_level  Log level (see log.h)
@@ -124,10 +137,29 @@ 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 (recursive) {
+    if (!did_msg) {
+      did_msg = true;
+      char *arg1 = func_name ? xstrdup(func_name) : (context ? xstrdup(context) : NULL);
+      multiqueue_put(main_loop.events, on_log_recursive_event, 2, arg1, line_num);
+    }
+    g_stats.log_skip++;
+    return false;
+  }
+
   if (log_level < MIN_LOG_LEVEL) {
     return false;
   }
@@ -139,6 +171,7 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
 #endif
 
   log_lock();
+  recursive = true;
   bool ret = false;
   FILE *log_file = open_log_file();
 
@@ -156,6 +189,7 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
     fclose(log_file);
   }
 end:
+  recursive = false;
   log_unlock();
   return ret;
 }
@@ -184,21 +218,17 @@ end:
 /// @return FILE* decided by log_path_init() or stderr in case of error
 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;
+  static bool recursive = false;
+  if (recursive) {
+    abort();
   }
 
   FILE *log_file = NULL;
-  opening_log_file = true;
+  recursive = true;
   if (log_path_init()) {
     log_file = fopen(log_file_path, "a");
   }
-  opening_log_file = false;
+  recursive = false;
 
   if (log_file != NULL) {
     return log_file;
@@ -208,9 +238,8 @@ FILE *open_log_file(void)
   //  - LOG() is called before early_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 $" LOG_FILE_ENV ": %s", log_file_path);
   return stderr;
 }
 
@@ -237,8 +266,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) {
@@ -285,12 +313,12 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
   FUNC_ATTR_PRINTF(7, 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;