Merge #6827 'Always enable logging'

13 files changed, 146 insertions, 94 deletions

diff --git a/src/nvim/cursor_shape.c b/src/nvim/cursor_shape.c
index e302d5aa4c..97fc3a3ca3 100644
--- a/src/nvim/cursor_shape.c
+++ b/src/nvim/cursor_shape.c
@@ -260,7 +260,7 @@ int cursor_mode_str2int(const char *mode)
       return current_mode;
     }
   }
-  ELOG("Unknown mode %s", mode);
+  WLOG("Unknown mode %s", mode);
   return -1;
 }
 
diff --git a/src/nvim/eval.c b/src/nvim/eval.c
index 94916e3e3c..baa61a26bc 100644
--- a/src/nvim/eval.c
+++ b/src/nvim/eval.c
@@ -14362,7 +14362,7 @@ static void f_serverstart(typval_T *argvars, typval_T *rettv, FunPtr fptr)
 
   if (result != 0) {
     EMSG2("Failed to start server: %s",
-          result > 0 ? "Unknonwn system error" : uv_strerror(result));
+          result > 0 ? "Unknown system error" : uv_strerror(result));
     return;
   }
 
diff --git a/src/nvim/event/loop.c b/src/nvim/event/loop.c
index c709ce9a1c..25701a1621 100644
--- a/src/nvim/event/loop.c
+++ b/src/nvim/event/loop.c
@@ -8,6 +8,7 @@
 
 #include "nvim/event/loop.h"
 #include "nvim/event/process.h"
+#include "nvim/log.h"
 
 #ifdef INCLUDE_GENERATED_DECLARATIONS
 # include "event/loop.c.generated.h"
@@ -78,20 +79,34 @@ void loop_on_put(MultiQueue *queue, void *data)
   uv_stop(&loop->uv);
 }
 
-void loop_close(Loop *loop, bool wait)
+/// @returns false if the loop could not be closed gracefully
+bool loop_close(Loop *loop, bool wait)
 {
+  bool rv = true;
   uv_mutex_destroy(&loop->mutex);
   uv_close((uv_handle_t *)&loop->children_watcher, NULL);
   uv_close((uv_handle_t *)&loop->children_kill_timer, NULL);
   uv_close((uv_handle_t *)&loop->poll_timer, NULL);
   uv_close((uv_handle_t *)&loop->async, NULL);
-  do {
+  uint64_t start = wait ? os_hrtime() : 0;
+  while (true) {
     uv_run(&loop->uv, wait ? UV_RUN_DEFAULT : UV_RUN_NOWAIT);
-  } while (uv_loop_close(&loop->uv) && wait);
+    if (!uv_loop_close(&loop->uv) || !wait) {
+      break;
+    }
+    if (os_hrtime() - start >= 2 * 1000000000) {
+      // Some libuv resource was not correctly deref'd. Log and bail.
+      rv = false;
+      ELOG("uv_loop_close() hang?");
+      log_uv_handles(&loop->uv);
+      break;
+    }
+  }
   multiqueue_free(loop->fast_events);
   multiqueue_free(loop->thread_events);
   multiqueue_free(loop->events);
   kl_destroy(WatcherPtr, loop->children);
+  return rv;
 }
 
 void loop_purge(Loop *loop)
diff --git a/src/nvim/garray.h b/src/nvim/garray.h
index 5d7806bbfa..94e1b61671 100644
--- a/src/nvim/garray.h
+++ b/src/nvim/garray.h
@@ -37,7 +37,7 @@ typedef struct growarray {
 static inline void *ga_append_via_ptr(garray_T *gap, size_t item_size)
 {
   if ((int)item_size != gap->ga_itemsize) {
-    ELOG("wrong item size in garray(%d), should be %d", item_size);
+    WLOG("wrong item size (%d), should be %d", item_size, gap->ga_itemsize);
   }
   ga_grow(gap, 1);
   return ((char *)gap->ga_data) + (item_size * (size_t)gap->ga_len++);
diff --git a/src/nvim/log.c b/src/nvim/log.c
index d059e28d5d..f1dbe61dda 100644
--- a/src/nvim/log.c
+++ b/src/nvim/log.c
@@ -7,20 +7,17 @@
 #include <stdbool.h>
 #include <stdint.h>
 #include <stdio.h>
+#include <uv.h>
 
 #include "nvim/log.h"
 #include "nvim/types.h"
 #include "nvim/os/os.h"
 #include "nvim/os/time.h"
 
-/// First location of the log file used by log_path_init()
-#define USR_LOG_FILE "$NVIM_LOG_FILE"
+#define LOG_FILE_ENV "NVIM_LOG_FILE"
 
-/// Fall back location of the log file used by log_path_init()
-#define USR_LOG_FILE_2 "$HOME" _PATHSEPSTR ".nvimlog"
-
-/// Cached location of the log file set by log_path_init()
-static char expanded_log_file_path[MAXPATHL + 1] = { 0 };
+/// Cached location of the expanded log file path decided by log_path_init().
+static char log_file_path[MAXPATHL + 1] = { 0 };
 
 static uv_mutex_t mutex;
 
@@ -28,31 +25,53 @@ static uv_mutex_t mutex;
 # include "log.c.generated.h"
 #endif
 
-/// Initialize path to log file
+static bool log_try_create(char *fname)
+{
+  if (fname == NULL || fname[0] == '\0') {
+    return false;
+  }
+  FILE *log_file = fopen(fname, "a");
+  if (log_file == NULL) {
+    return false;
+  }
+  fclose(log_file);
+  return true;
+}
+
+/// Initializes path to log file. Sets $NVIM_LOG_FILE if empty.
 ///
-/// Tries to use #USR_LOG_FILE, then falls back #USR_LOG_FILE_2. Path to log
+/// Tries $NVIM_LOG_FILE, or falls back to $XDG_DATA_HOME/nvim/log. Path to log
 /// file is cached, so only the first call has effect, unless first call was not
-/// successful. To make initialization not succeed either a bug in expand_env()
-/// is needed or both `$NVIM_LOG_FILE` and `$HOME` environment variables
-/// undefined.
+/// successful. Failed initialization indicates either a bug in expand_env()
+/// or both $NVIM_LOG_FILE and $HOME environment variables are undefined.
 ///
 /// @return true if path was initialized, false otherwise.
 static bool log_path_init(void)
 {
-  if (expanded_log_file_path[0]) {
+  if (log_file_path[0]) {
     return true;
   }
-  expand_env((char_u *)USR_LOG_FILE, (char_u *)expanded_log_file_path,
-             sizeof(expanded_log_file_path) - 1);
-  // if the log file path expansion failed then fall back to stderr
-  if (strcmp(USR_LOG_FILE, expanded_log_file_path) == 0) {
-    memset(expanded_log_file_path, 0, sizeof(expanded_log_file_path));
-    expand_env((char_u *)USR_LOG_FILE_2, (char_u *)expanded_log_file_path,
-               sizeof(expanded_log_file_path) - 1);
-    if (strcmp(USR_LOG_FILE_2, expanded_log_file_path) == 0) {
-      memset(expanded_log_file_path, 0, sizeof(expanded_log_file_path));
+  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)
+      || log_file_path[0] == '\0'
+      || os_isdir((char_u *)log_file_path)
+      || !log_try_create(log_file_path)) {
+    // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
+    char *defaultpath = stdpaths_user_data_subpath("log", 0, true);
+    size_t len = xstrlcpy(log_file_path, defaultpath, size);
+    xfree(defaultpath);
+    // Fall back to .nvimlog
+    if (len >= size || !log_try_create(log_file_path)) {
+      len = xstrlcpy(log_file_path, ".nvimlog", size);
+    }
+    // Fall back to stderr
+    if (len >= size || !log_try_create(log_file_path)) {
+      log_file_path[0] = '\0';
       return false;
     }
+    os_setenv(LOG_FILE_ENV, log_file_path, true);
   }
   return true;
 }
@@ -75,6 +94,10 @@ void log_unlock(void)
 bool do_log(int log_level, const char *func_name, int line_num, bool eol,
             const char* fmt, ...) FUNC_ATTR_UNUSED
 {
+  if (log_level < MIN_LOG_LEVEL) {
+    return false;
+  }
+
   log_lock();
   bool ret = false;
   FILE *log_file = open_log_file();
@@ -97,26 +120,42 @@ end:
   return ret;
 }
 
+void log_uv_handles(void *loop)
+{
+  uv_loop_t *l = 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 The FILE* specified by the USR_LOG_FILE path or stderr in case of
-///         error
+/// @return FILE* decided by log_path_init() or stderr in case of error
 FILE *open_log_file(void)
 {
   static bool opening_log_file = false;
-
   // check if it's a recursive call
   if (opening_log_file) {
     do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, true,
-                   "Trying to LOG() recursively! Please fix it.");
+                   "Cannot LOG() recursively.");
     return stderr;
   }
 
-  // expand USR_LOG_FILE if needed and open the file
   FILE *log_file = NULL;
   opening_log_file = true;
   if (log_path_init()) {
-    log_file = fopen(expanded_log_file_path, "a");
+    log_file = fopen(log_file_path, "a");
   }
   opening_log_file = false;
 
@@ -124,10 +163,13 @@ FILE *open_log_file(void)
     return log_file;
   }
 
+  // May happen if:
+  //  - LOG() is called before early_init()
+  //  - Directory does not exist
+  //  - File is not writable
   do_log_to_file(stderr, ERROR_LOG_LEVEL, __func__, __LINE__, true,
-                 "Couldn't open USR_LOG_FILE, logging to stderr! This may be "
-                 "caused by attempting to LOG() before initialization "
-                 "functions are called (e.g. init_homedir()).");
+                 "Logging to stderr, failed to open $" LOG_FILE_ENV ": %s",
+                 log_file_path);
   return stderr;
 }
 
@@ -152,7 +194,7 @@ static bool v_do_log_to_file(FILE *log_file, int log_level,
     [DEBUG_LOG_LEVEL]   = "DEBUG",
     [INFO_LOG_LEVEL]    = "INFO ",
     [WARNING_LOG_LEVEL] = "WARN ",
-    [ERROR_LOG_LEVEL]   = "ERROR"
+    [ERROR_LOG_LEVEL]   = "ERROR",
   };
   assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL);
 
diff --git a/src/nvim/log.h b/src/nvim/log.h
index 32b7276f14..221f0bbaf6 100644
--- a/src/nvim/log.h
+++ b/src/nvim/log.h
@@ -18,55 +18,47 @@
 #define ELOG(...)
 #define ELOGN(...)
 
-// Logging is disabled if NDEBUG or DISABLE_LOG is defined.
-#if !defined(DISABLE_LOG) && defined(NDEBUG)
-#  define DISABLE_LOG
-#endif
-
-// MIN_LOG_LEVEL can be defined during compilation to adjust the desired level
-// of logging. INFO_LOG_LEVEL is used by default.
 #ifndef MIN_LOG_LEVEL
 #  define MIN_LOG_LEVEL INFO_LOG_LEVEL
 #endif
 
-#ifndef DISABLE_LOG
-
-#  if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
-#    undef DLOG
-#    undef DLOGN
-#    define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
-#    define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
-#  endif
+#define LOG(level, ...) do_log((level), __func__, __LINE__, true, \
+                               __VA_ARGS__)
 
-#  if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
-#    undef ILOG
-#    undef ILOGN
-#    define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
-#    define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
-#  endif
+#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
+# undef DLOG
+# undef DLOGN
+# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \
+                          __VA_ARGS__)
+# define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \
+                           __VA_ARGS__)
+#endif
 
-#  if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL
-#    undef WLOG
-#    undef WLOGN
-#    define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
-#    define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
-#  endif
+#if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
+# undef ILOG
+# undef ILOGN
+# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \
+                          __VA_ARGS__)
+# define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \
+                           __VA_ARGS__)
+#endif
 
-#  if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL
-#    undef ELOG
-#    undef ELOGN
-#    define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
-#    define ELOGN(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
-#  endif
+#if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL
+# undef WLOG
+# undef WLOGN
+# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \
+                          __VA_ARGS__)
+# define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \
+                           __VA_ARGS__)
+#endif
 
+#if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL
+# undef ELOG
+# undef ELOGN
+# define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, true, \
+                          __VA_ARGS__)
+# define ELOGN(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, false, \
+                           __VA_ARGS__)
 #endif
 
 #ifdef INCLUDE_GENERATED_DECLARATIONS
diff --git a/src/nvim/main.c b/src/nvim/main.c
index 46607da6ea..19a661d7db 100644
--- a/src/nvim/main.c
+++ b/src/nvim/main.c
@@ -153,10 +153,11 @@ void event_init(void)
   terminal_init();
 }
 
-void event_teardown(void)
+/// @returns false if main_loop could not be closed gracefully
+bool event_teardown(void)
 {
   if (!main_loop.events) {
-    return;
+    return true;
   }
 
   multiqueue_process_events(main_loop.events);
@@ -168,7 +169,7 @@ void event_teardown(void)
   signal_teardown();
   terminal_teardown();
 
-  loop_close(&main_loop, true);
+  return loop_close(&main_loop, true);
 }
 
 /// Performs early initialization.
diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c
index 413b800af5..68ac35bc4e 100644
--- a/src/nvim/msgpack_rpc/channel.c
+++ b/src/nvim/msgpack_rpc/channel.c
@@ -370,7 +370,7 @@ static void receive_msgpack(Stream *stream, RBuffer *rbuf, size_t c,
     char buf[256];
     snprintf(buf, sizeof(buf), "ch %" PRIu64 " was closed by the client",
              channel->id);
-    call_set_error(channel, buf);
+    call_set_error(channel, buf, WARNING_LOG_LEVEL);
     goto end;
   }
 
@@ -409,7 +409,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);
+        call_set_error(channel, buf, ERROR_LOG_LEVEL);
       }
       msgpack_unpacked_destroy(&unpacked);
       // Bail out from this event loop iteration
@@ -459,7 +459,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);
+      call_set_error(channel, buf, ERROR_LOG_LEVEL);
     }
     api_clear_error(&error);
     return;
@@ -564,7 +564,7 @@ static bool channel_write(Channel *channel, WBuffer *buffer)
              "Before returning from a RPC call, ch %" PRIu64 " was "
              "closed due to a failed write",
              channel->id);
-    call_set_error(channel, buf);
+    call_set_error(channel, buf, ERROR_LOG_LEVEL);
   }
 
   return success;
@@ -795,9 +795,9 @@ static void complete_call(msgpack_object *obj, Channel *channel)
   }
 }
 
-static void call_set_error(Channel *channel, char *msg)
+static void call_set_error(Channel *channel, char *msg, int loglevel)
 {
-  ELOG("RPC: %s", msg);
+  LOG(loglevel, "RPC: %s", msg);
   for (size_t i = 0; i < kv_size(channel->call_stack); i++) {
     ChannelCallFrame *frame = kv_A(channel->call_stack, i);
     frame->returned = true;
diff --git a/src/nvim/msgpack_rpc/server.c b/src/nvim/msgpack_rpc/server.c
index c9edd05dc2..1e0cc27886 100644
--- a/src/nvim/msgpack_rpc/server.c
+++ b/src/nvim/msgpack_rpc/server.c
@@ -125,7 +125,7 @@ bool server_owns_pipe_address(const char *path)
 int server_start(const char *endpoint)
 {
   if (endpoint == NULL || endpoint[0] == '\0') {
-    ELOG("Empty or NULL endpoint");
+    WLOG("Empty or NULL endpoint");
     return 1;
   }
 
@@ -151,7 +151,7 @@ int server_start(const char *endpoint)
 
   result = socket_watcher_start(watcher, MAX_CONNECTIONS, connection_cb);
   if (result < 0) {
-    ELOG("Failed to start server: %s", uv_strerror(result));
+    WLOG("Failed to start server: %s", uv_strerror(result));
     socket_watcher_close(watcher, free_server);
     return result;
   }
diff --git a/src/nvim/os/shell.c b/src/nvim/os/shell.c
index 1a40309655..8767287cf3 100644
--- a/src/nvim/os/shell.c
+++ b/src/nvim/os/shell.c
@@ -685,7 +685,7 @@ static void shell_write_cb(Stream *stream, void *data, int status)
                        uv_err_name(status));
   }
   if (stream->closed) {  // Process may have exited before this write.
-    ELOG("stream was already closed");
+    WLOG("stream was already closed");
     return;
   }
   stream_close(stream, NULL, NULL);
diff --git a/src/nvim/os_unix.c b/src/nvim/os_unix.c
index fb648fbcf8..692bcc97f4 100644
--- a/src/nvim/os_unix.c
+++ b/src/nvim/os_unix.c
@@ -141,7 +141,9 @@ void mch_exit(int r) FUNC_ATTR_NORETURN
   ui_flush();
   ml_close_all(true);           // remove all memfiles
 
-  event_teardown();
+  if (!event_teardown() && r == 0) {
+    r = 1;  // Exit with error if main_loop did not teardown gracefully.
+  }
   stream_set_blocking(input_global_fd(), true);  // normalize stream (#2598)
 
 #ifdef EXITFREE
diff --git a/src/nvim/testdir/runtest.vim b/src/nvim/testdir/runtest.vim
index fa3c0a6ad0..117ba52eb6 100644
--- a/src/nvim/testdir/runtest.vim
+++ b/src/nvim/testdir/runtest.vim
@@ -74,7 +74,7 @@ set backspace=
 set nohidden smarttab noautoindent noautoread complete-=i noruler noshowcmd
 set listchars=eol:$
 " Prevent Nvim log from writing to stderr.
-let $NVIM_LOG_FILE='Xnvim.log'
+let $NVIM_LOG_FILE = exists($NVIM_LOG_FILE) ? $NVIM_LOG_FILE : 'Xnvim.log'
 
 func RunTheTest(test)
   echo 'Executing ' . a:test
diff --git a/src/nvim/testdir/shared.vim b/src/nvim/testdir/shared.vim
index 784e4a0a02..72cfea96c6 100644
--- a/src/nvim/testdir/shared.vim
+++ b/src/nvim/testdir/shared.vim
@@ -187,7 +187,7 @@ func RunVim(before, after, arguments)
 endfunc
 
 func RunVimPiped(before, after, arguments, pipecmd)
-  let $NVIM_LOG_FILE='Xnvim.log'
+  let $NVIM_LOG_FILE = exists($NVIM_LOG_FILE) ? $NVIM_LOG_FILE : 'Xnvim.log'
   let cmd = GetVimCommand()
   if cmd == ''
     return 0