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.

9 files changed, 85 insertions, 65 deletions

diff --git a/src/nvim/README.md b/src/nvim/README.md
index 9417629691..f0b7339352 100644
--- a/src/nvim/README.md
+++ b/src/nvim/README.md
@@ -23,7 +23,7 @@ Logs
 
 Low-level log messages sink to `$NVIM_LOG_FILE`.
 
-UI events are logged at DEBUG level (`DEBUG_LOG_LEVEL`).
+UI events are logged at DEBUG level (`LOGLVL_DBG`).
 
     rm -rf build/
     make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0"
diff --git a/src/nvim/channel.c b/src/nvim/channel.c
index 7a71be58c1..ecc3a24784 100644
--- a/src/nvim/channel.c
+++ b/src/nvim/channel.c
@@ -188,7 +188,7 @@ Channel *channel_alloc(ChannelStreamType type)
 
 void channel_create_event(Channel *chan, const char *ext_source)
 {
-#if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_INF
   const char *source;
 
   if (ext_source) {
diff --git a/src/nvim/generators/gen_api_dispatch.lua b/src/nvim/generators/gen_api_dispatch.lua
index 38aca32f33..0f7052d351 100644
--- a/src/nvim/generators/gen_api_dispatch.lua
+++ b/src/nvim/generators/gen_api_dispatch.lua
@@ -212,8 +212,8 @@ for i = 1, #functions do
 
     output:write('Object handle_'..fn.name..'(uint64_t channel_id, Array args, Error *error)')
     output:write('\n{')
-    output:write('\n#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL')
-    output:write('\n  logmsg(DEBUG_LOG_LEVEL, "RPC: ", NULL, -1, true, "ch %" PRIu64 ": invoke '
+    output:write('\n#if MIN_LOG_LEVEL <= LOGLVL_DBG')
+    output:write('\n  logmsg(LOGLVL_DBG, "RPC: ", NULL, -1, true, "ch %" PRIu64 ": invoke '
                  ..fn.name..'", channel_id);')
     output:write('\n#endif')
     output:write('\n  Object ret = NIL;')
diff --git a/src/nvim/globals.h b/src/nvim/globals.h
index b0006ebaca..106e6a7828 100644
--- a/src/nvim/globals.h
+++ b/src/nvim/globals.h
@@ -76,7 +76,8 @@
 EXTERN struct nvim_stats_s {
   int64_t fsync;
   int64_t redraw;
-} g_stats INIT(= { 0, 0 });
+  int16_t log_skip;  // How many logs were tried and skipped before log_init.
+} g_stats INIT(= { 0, 0, 0 });
 
 // Values for "starting".
 #define NO_SCREEN       2       // no screen updating yet
@@ -1029,7 +1030,7 @@ EXTERN FILE *time_fd INIT(= NULL);  // where to write startup timing
 // the warning.
 EXTERN int vim_ignored;
 
-// Start a msgpack-rpc channel over stdin/stdout.
+// stdio is an RPC channel (--embed).
 EXTERN bool embedded_mode INIT(= false);
 // Do not start a UI nor read/write to stdio (unless embedding).
 EXTERN bool headless_mode INIT(= false);
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;
diff --git a/src/nvim/log.h b/src/nvim/log.h
index 724d073d02..cbee0e0f81 100644
--- a/src/nvim/log.h
+++ b/src/nvim/log.h
@@ -16,11 +16,11 @@
 # define NVIM_PROBE(name, n, ...)
 #endif
 
-#define TRACE_LOG_LEVEL 0
-#define DEBUG_LOG_LEVEL 1
-#define INFO_LOG_LEVEL 2
-#define WARN_LOG_LEVEL 3
-#define ERROR_LOG_LEVEL 4
+#define LOGLVL_TRC 0
+#define LOGLVL_DBG 1
+#define LOGLVL_INF 2
+#define LOGLVL_WRN 3
+#define LOGLVL_ERR 4
 
 #define DLOG(...)
 #define DLOGN(...)
@@ -32,46 +32,37 @@
 #define ELOGN(...)
 
 #ifndef MIN_LOG_LEVEL
-# define MIN_LOG_LEVEL INFO_LOG_LEVEL
+# define MIN_LOG_LEVEL LOGLVL_INF
 #endif
 
-#define LOG(level, ...) logmsg((level), NULL, __func__, __LINE__, true, \
-                               __VA_ARGS__)
+#define LOG(level, ...) logmsg((level), NULL, __func__, __LINE__, true, __VA_ARGS__)
 
-#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_DBG
 # undef DLOG
 # undef DLOGN
-# define DLOG(...) logmsg(DEBUG_LOG_LEVEL, NULL, __func__, __LINE__, true, \
-                          __VA_ARGS__)
-# define DLOGN(...) logmsg(DEBUG_LOG_LEVEL, NULL, __func__, __LINE__, false, \
-                           __VA_ARGS__)
+# define DLOG(...) logmsg(LOGLVL_DBG, NULL, __func__, __LINE__, true, __VA_ARGS__)
+# define DLOGN(...) logmsg(LOGLVL_DBG, NULL, __func__, __LINE__, false, __VA_ARGS__)
 #endif
 
-#if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_INF
 # undef ILOG
 # undef ILOGN
-# define ILOG(...) logmsg(INFO_LOG_LEVEL, NULL, __func__, __LINE__, true, \
-                          __VA_ARGS__)
-# define ILOGN(...) logmsg(INFO_LOG_LEVEL, NULL, __func__, __LINE__, false, \
-                           __VA_ARGS__)
+# define ILOG(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, true, __VA_ARGS__)
+# define ILOGN(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, false, __VA_ARGS__)
 #endif
 
-#if MIN_LOG_LEVEL <= WARN_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_WRN
 # undef WLOG
 # undef WLOGN
-# define WLOG(...) logmsg(WARN_LOG_LEVEL, NULL, __func__, __LINE__, true, \
-                          __VA_ARGS__)
-# define WLOGN(...) logmsg(WARN_LOG_LEVEL, NULL, __func__, __LINE__, false, \
-                           __VA_ARGS__)
+# define WLOG(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, true, __VA_ARGS__)
+# define WLOGN(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, false, __VA_ARGS__)
 #endif
 
-#if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_ERR
 # undef ELOG
 # undef ELOGN
-# define ELOG(...) logmsg(ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true, \
-                          __VA_ARGS__)
-# define ELOGN(...) logmsg(ERROR_LOG_LEVEL, NULL, __func__, __LINE__, false, \
-                           __VA_ARGS__)
+# define ELOG(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, true, __VA_ARGS__)
+# define ELOGN(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, false, __VA_ARGS__)
 #endif
 
 #ifdef HAVE_EXECINFO_BACKTRACE
diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c
index 79ecd9f827..287310cc34 100644
--- a/src/nvim/msgpack_rpc/channel.c
+++ b/src/nvim/msgpack_rpc/channel.c
@@ -31,7 +31,7 @@
 #include "nvim/ui.h"
 #include "nvim/vim.h"
 
-#if MIN_LOG_LEVEL > DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL > LOGLVL_DBG
 # define log_client_msg(...)
 # define log_server_msg(...)
 #endif
@@ -62,7 +62,7 @@ void rpc_start(Channel *channel)
 
   if (channel->streamtype != kChannelStreamInternal) {
     Stream *out = channel_outstream(channel);
-#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_DBG
     Stream *in = channel_instream(channel);
     DLOG("rpc ch %" PRIu64 " in-stream=%p out-stream=%p", channel->id,
          (void *)in, (void *)out);
@@ -209,7 +209,7 @@ static void receive_msgpack(Stream *stream, RBuffer *rbuf, size_t c, void *data,
     char buf[256];
     snprintf(buf, sizeof(buf), "ch %" PRIu64 " was closed by the client",
              channel->id);
-    call_set_error(channel, buf, INFO_LOG_LEVEL);
+    call_set_error(channel, buf, LOGLVL_INF);
     goto end;
   }
 
@@ -249,7 +249,7 @@ static void parse_msgpack(Channel *channel)
                  "ch %" PRIu64 " returned a response with an unknown request "
                  "id. Ensure the client is properly synchronized",
                  channel->id);
-        call_set_error(channel, buf, ERROR_LOG_LEVEL);
+        call_set_error(channel, buf, LOGLVL_ERR);
       }
       msgpack_unpacked_destroy(&unpacked);
     } else {
@@ -299,7 +299,7 @@ static void handle_request(Channel *channel, msgpack_object *request)
       snprintf(buf, sizeof(buf),
                "ch %" PRIu64 " sent an invalid message, closed.",
                channel->id);
-      call_set_error(channel, buf, ERROR_LOG_LEVEL);
+      call_set_error(channel, buf, LOGLVL_ERR);
     }
     api_clear_error(&error);
     return;
@@ -418,7 +418,7 @@ static bool channel_write(Channel *channel, WBuffer *buffer)
              "ch %" PRIu64 ": stream write failed. "
              "RPC canceled; closing channel",
              channel->id);
-    call_set_error(channel, buf, ERROR_LOG_LEVEL);
+    call_set_error(channel, buf, LOGLVL_ERR);
   }
 
   return success;
@@ -693,7 +693,7 @@ const char *rpc_client_name(Channel *chan)
   return NULL;
 }
 
-#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL <= LOGLVL_DBG
 # define REQ "[request]  "
 # define RES "[response] "
 # define NOT "[notify]   "
diff --git a/src/nvim/state.c b/src/nvim/state.c
index f6d9b535fc..f075dd772a 100644
--- a/src/nvim/state.c
+++ b/src/nvim/state.c
@@ -81,8 +81,8 @@ getkey:
       may_sync_undo();
     }
 
-#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
-    log_key(DEBUG_LOG_LEVEL, key);
+#if MIN_LOG_LEVEL <= LOGLVL_DBG
+    log_key(LOGLVL_DBG, key);
 #endif
 
     int execute_result = s->execute(s, key);
diff --git a/src/nvim/ui.c b/src/nvim/ui.c
index b40033296e..d66e57b13b 100644
--- a/src/nvim/ui.c
+++ b/src/nvim/ui.c
@@ -64,7 +64,7 @@ static handle_T cursor_grid_handle = DEFAULT_GRID_HANDLE;
 static bool has_mouse = false;
 static int pending_has_mouse = -1;
 
-#if MIN_LOG_LEVEL > DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL > LOGLVL_DBG
 # define UI_LOG(funname)
 #else
 static size_t uilog_seen = 0;
@@ -82,10 +82,10 @@ static char uilog_last_event[1024] = { 0 };
       uilog_seen++; \
     } else { \
       if (uilog_seen > 0) { \
-        logmsg(DEBUG_LOG_LEVEL, "UI: ", NULL, -1, true, \
+        logmsg(LOGLVL_DBG, "UI: ", NULL, -1, true, \
                "%s (+%zu times...)", uilog_last_event, uilog_seen); \
       } \
-      logmsg(DEBUG_LOG_LEVEL, "UI: ", NULL, -1, true, STR(funname)); \
+      logmsg(LOGLVL_DBG, "UI: ", NULL, -1, true, STR(funname)); \
       uilog_seen = 0; \
       xstrlcpy(uilog_last_event, STR(funname), sizeof(uilog_last_event)); \
     } \