Merge #6827 'Always enable logging'

.travis.yml

@@ -21,14 +21,15 @@ env:
     - INSTALL_PREFIX="$HOME/nvim-install"
     # Log directory for Clang sanitizers and Valgrind.
     - LOG_DIR="$BUILD_DIR/log"
+    # Nvim log file.
+    - NVIM_LOG_FILE="$BUILD_DIR/.nvimlog"
     # Default CMake flags.
     - CMAKE_FLAGS="-DTRAVIS_CI_BUILD=ON
                    -DCMAKE_BUILD_TYPE=Debug
                    -DCMAKE_INSTALL_PREFIX:PATH=$INSTALL_PREFIX
                    -DBUSTED_OUTPUT_TYPE=nvim
                    -DDEPS_PREFIX=$DEPS_BUILD_DIR/usr
-                   -DMIN_LOG_LEVEL=3
+                   -DMIN_LOG_LEVEL=3"
-                   -DDISABLE_LOG=1"
     - DEPS_CMAKE_FLAGS="-DDEPS_DOWNLOAD_DIR:PATH=$DEPS_DOWNLOAD_DIR"
     # Additional CMake flags for 32-bit builds.
     - CMAKE_FLAGS_32BIT="-DCMAKE_SYSTEM_LIBRARY_PATH=/lib32:/usr/lib32:/usr/local/lib32

CMakeLists.txt

@@ -96,15 +96,15 @@ if(CMAKE_C_FLAGS_RELEASE MATCHES "-O3")
   string(REPLACE "-O3" "-O2" CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE}")
 endif()
 
-# Disable logging for release-type builds.
+# Minimize logging for release-type builds.
-if(NOT CMAKE_C_FLAGS_RELEASE MATCHES DDISABLE_LOG)
+if(NOT CMAKE_C_FLAGS_RELEASE MATCHES DMIN_LOG_LEVEL)
-  set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} -DDISABLE_LOG")
+  set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} -DMIN_LOG_LEVEL=3")
 endif()
-if(NOT CMAKE_C_FLAGS_MINSIZEREL MATCHES DDISABLE_LOG)
+if(NOT CMAKE_C_FLAGS_MINSIZEREL MATCHES DMIN_LOG_LEVEL)
-  set(CMAKE_C_FLAGS_MINSIZEREL "${CMAKE_C_FLAGS_MINSIZEREL} -DDISABLE_LOG")
+  set(CMAKE_C_FLAGS_MINSIZEREL "${CMAKE_C_FLAGS_MINSIZEREL} -DMIN_LOG_LEVEL=3")
 endif()
-if(NOT CMAKE_C_FLAGS_RELWITHDEBINFO MATCHES DDISABLE_LOG)
+if(NOT CMAKE_C_FLAGS_RELWITHDEBINFO MATCHES DMIN_LOG_LEVEL)
-  set(CMAKE_C_FLAGS_RELWITHDEBINFO "${CMAKE_C_FLAGS_RELWITHDEBINFO} -DDISABLE_LOG")
+  set(CMAKE_C_FLAGS_RELWITHDEBINFO "${CMAKE_C_FLAGS_RELWITHDEBINFO} -DMIN_LOG_LEVEL=3")
 endif()
 
 # Enable assertions for RelWithDebInfo.
@@ -463,11 +463,11 @@ install_helper(
 # MIN_LOG_LEVEL for log.h
 if(DEFINED MIN_LOG_LEVEL)
   if(NOT MIN_LOG_LEVEL MATCHES "^[0-3]$")
-    message(FATAL_ERROR "MIN_LOG_LEVEL must be a number 0-3")
+    message(FATAL_ERROR "invalid MIN_LOG_LEVEL: " ${MIN_LOG_LEVEL})
   endif()
   message(STATUS "MIN_LOG_LEVEL set to ${MIN_LOG_LEVEL}")
 else()
-  message(STATUS "MIN_LOG_LEVEL not specified, defaulting to INFO(1)")
+  message(STATUS "MIN_LOG_LEVEL not specified, defaulting to 1 (INFO)")
 endif()
 
 # Go down the tree.

CONTRIBUTING.md

@@ -6,7 +6,7 @@ Getting started
 If you want to help but don't know where to start, here are some
 low-risk/isolated tasks:
 
-- Merge a [Vim patch].
+- [Merge a Vim patch].
 - Try a [complexity:low] issue.
 - Fix bugs found by [clang scan-build](#clang-scan-build),
   [coverity](#coverity), and [PVS](#pvs-studio).
@@ -23,18 +23,16 @@ Reporting problems
 - Check the [**FAQ**][wiki-faq].
 - Search [existing issues][github-issues] (including closed!)
 - Update Neovim to the latest version to see if your problem persists.
-- If you're using a plugin manager, comment out your plugins, then add them back
+- Disable plugins incrementally, to narrow down the cause of the issue.
-  in one by one, to narrow down the cause of the issue.
+- When reporting a crash, include a stacktrace.
-- Crash reports which include a stacktrace are 10x more valuable.
+- [Bisect][git-bisect] to the cause of a regression, if you are able. This is _extremely_ helpful.
-- [Bisecting][git-bisect] to the cause of a regression often leads to an
+- Check `$NVIM_LOG_FILE`, if it exists.
-  immediate fix.
 
 Pull requests ("PRs")
 ---------------------
 
 - To avoid duplicate work, create a `[WIP]` pull request as soon as possible.
-- Avoid cosmetic changes to unrelated files in the same commit: noise makes
+- Avoid cosmetic changes to unrelated files in the same commit.
-  reviews take longer.
 - Use a [feature branch][git-feature-branch] instead of the master branch.
 - Use a **rebase workflow** for small PRs.
   - After addressing review comments, it's fine to rebase and force-push.
@@ -87,10 +85,11 @@ the VCS/git logs more valuable.
 
 ### Automated builds (CI)
 
-Each pull request must pass the automated builds ([travis CI] and [quickbuild]).
+Each pull request must pass the automated builds on [travis CI], [quickbuild]
+and [AppVeyor].
 
-- CI builds are compiled with [`-Werror`][gcc-warnings], so if your PR
+- CI builds are compiled with [`-Werror`][gcc-warnings], so compiler warnings
-  introduces any compiler warnings, the build will fail.
+  will fail the build.
 - If any tests fail, the build will fail.
   See [Building Neovim#running-tests][wiki-run-tests] to run tests locally.
   Passing locally doesn't guarantee passing the CI build, because of the
@@ -173,6 +172,7 @@ as context, use the `-W` argument as well.
 [3174]: https://github.com/neovim/neovim/issues/3174
 [travis CI]: https://travis-ci.org/neovim/neovim
 [quickbuild]: http://neovim-qb.szakmeister.net/dashboard
-[Vim patch]: https://github.com/neovim/neovim/wiki/Merging-patches-from-upstream-Vim
+[AppVeyor]: https://ci.appveyor.com/project/neovim/neovim
+[Merge a Vim patch]: https://github.com/neovim/neovim/wiki/Merging-patches-from-upstream-Vim
 [clang-scan]: https://neovim.io/doc/reports/clang/
 [complexity:low]: https://github.com/neovim/neovim/issues?q=is%3Aopen+is%3Aissue+label%3Acomplexity%3Alow

ci/common/suite.sh

@@ -39,6 +39,13 @@ enter_suite() {
 
 exit_suite() {
   set +x
+  if test -f "$NVIM_LOG_FILE" ; then
+    printf "===============================================================================\n"
+    printf "NVIM_LOG_FILE: $NVIM_LOG_FILE\n"
+    cat "$NVIM_LOG_FILE" 2>/dev/null || printf '(empty)'
+    printf "\n"
+    rm -rf "$NVIM_LOG_FILE"
+  fi
   travis_fold end "${NVIM_TEST_CURRENT_SUITE}"
   if test $FAILED -ne 0 ; then
     echo "Suite ${NVIM_TEST_CURRENT_SUITE} failed, summary:"

cmake/RunTests.cmake

@@ -3,6 +3,10 @@ set(ENV{NVIM_RPLUGIN_MANIFEST} ${WORKING_DIR}/Xtest_rplugin_manifest)
 set(ENV{XDG_CONFIG_HOME} ${WORKING_DIR}/Xtest_xdg/config)
 set(ENV{XDG_DATA_HOME} ${WORKING_DIR}/Xtest_xdg/share)
 
+if(NOT DEFINED ENV{NVIM_LOG_FILE})
+  set(ENV{NVIM_LOG_FILE} ${WORKING_DIR}/.nvimlog)
+endif()
+
 if(NVIM_PRG)
   set(ENV{NVIM_PRG} "${NVIM_PRG}")
 endif()

contrib/local.mk.example

@@ -31,9 +31,8 @@
 #
 # CMAKE_BUILD_TYPE := Debug
 
-# By default, nvim's log level is INFO (1) (unless CMAKE_BUILD_TYPE is
+# The default log level is 1 (INFO) (unless CMAKE_BUILD_TYPE is "Release").
-# "Release", in which case logging is disabled).
+# Log levels: 0 (DEBUG), 1 (INFO), 2 (WARNING), 3 (ERROR)
-# The log level must be a number DEBUG (0), INFO (1), WARNING (2) or ERROR (3).
 # CMAKE_EXTRA_FLAGS += -DMIN_LOG_LEVEL=1
 
 # By default, nvim uses bundled versions of its required third-party

runtime/doc/starting.txt

@@ -1366,39 +1366,38 @@ file when reading and include:
   complete MessagePack object.
 
 ==============================================================================
-9. Base Directories				*base-directories* *xdg*
+9. Standard Paths
 
-Nvim conforms to the XDG Base Directory Specification for application
+Nvim stores configuration and data in standard locations. Plugins are strongly
-configuration and data file locations. This just means Nvim looks for some
+encouraged to follow this pattern also.
-optional settings and uses them if they exist, otherwise defaults are chosen.
+
+						      *base-directories* *xdg*
+The "base" (root) directories conform to the XDG Base Directory Specification.
 https://specifications.freedesktop.org/basedir-spec/basedir-spec-latest.html
+The $XDG_CONFIG_HOME and $XDG_DATA_HOME environment variables are used if they
+exist, otherwise default values (listed below) are used.
 
-CONFIGURATION DIRECTORY				*$XDG_CONFIG_HOME*
+Note: Throughout the user manual these defaults are used as placeholders, e.g.
+"~/.config" is understood to mean "$XDG_CONFIG_HOME or ~/.config".
 
-    Base directory default:
+CONFIG DIRECTORY					*$XDG_CONFIG_HOME*
-        Unix:     ~/.config
+          Base                Nvim ~
-        Windows:  ~/AppData/Local
+Unix:     ~/.config           ~/.config/nvim
+Windows:  ~/AppData/Local     ~/AppData/Local/nvim
 
-    Nvim directory:
+DATA DIRECTORY						*$XDG_DATA_HOME*
-        Unix:     ~/.config/nvim/
+          Base                Nvim ~
-        Windows:  ~/AppData/Local/nvim/
+Unix:     ~/.local/share      ~/.local/share/nvim
+Windows:  ~/AppData/Local     ~/AppData/Local/nvim-data
 
-DATA DIRECTORY					*$XDG_DATA_HOME*
+STANDARD PATHS						*standard-path*
 
-    Base directory default:
+							      *$NVIM_LOG_FILE*
-        Unix:     ~/.local/share
+Besides 'debug' and 'verbose', Nvim has a low-level "log of last resort" that
-        Windows:  ~/AppData/Local
+is written directly to the filesystem. This log may also be used by plugins or
-
+RPC clients for debugging. $NVIM_LOG_FILE contains the log file path: >
-    Nvim directory:
+	:echo $NVIM_LOG_FILE
-        Unix:     ~/.local/share/nvim/
+Usually the file is ~/.local/share/nvim/log unless that path is inaccessible
-        Windows:  ~/AppData/Local/nvim-data/
+or if $NVIM_LOG_FILE was set before |startup|.
-
-Note on Windows the configuration and data directory defaults are the same
-(for lack of an alternative), but the sub-directory for data is named
-"nvim-data" to separate it from the configuration sub-directory "nvim".
-
-Throughout other sections of the user manual, the defaults are used as generic
-placeholders, e.g. where "~/.config" is mentioned it should be understood to
-mean "$XDG_CONFIG_HOME or ~/.config".
 
  vim:tw=78:ts=8:ft=help:norl:

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;
 }
 

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;
   }
 

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)

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++);

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 LOG_FILE_ENV "NVIM_LOG_FILE"
-#define USR_LOG_FILE "$NVIM_LOG_FILE"
 
-/// Fall back location of the log file used by log_path_init()
+/// Cached location of the expanded log file path decided by log_path_init().
-#define USR_LOG_FILE_2 "$HOME" _PATHSEPSTR ".nvimlog"
+static char log_file_path[MAXPATHL + 1] = { 0 };
-
-/// Cached location of the log file set by log_path_init()
-static char expanded_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()
+/// successful. Failed initialization indicates either a bug in expand_env()
-/// is needed or both `$NVIM_LOG_FILE` and `$HOME` environment variables
+/// or both $NVIM_LOG_FILE and $HOME environment variables are undefined.
-/// 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,
+  size_t size = sizeof(log_file_path);
-             sizeof(expanded_log_file_path) - 1);
+  expand_env((char_u *)"$" LOG_FILE_ENV, (char_u *)log_file_path,
-  // if the log file path expansion failed then fall back to stderr
+             (int)size - 1);
-  if (strcmp(USR_LOG_FILE, expanded_log_file_path) == 0) {
+  if (strequal("$" LOG_FILE_ENV, log_file_path)
-    memset(expanded_log_file_path, 0, sizeof(expanded_log_file_path));
+      || log_file_path[0] == '\0'
-    expand_env((char_u *)USR_LOG_FILE_2, (char_u *)expanded_log_file_path,
+      || os_isdir((char_u *)log_file_path)
-               sizeof(expanded_log_file_path) - 1);
+      || !log_try_create(log_file_path)) {
-    if (strcmp(USR_LOG_FILE_2, expanded_log_file_path) == 0) {
+    // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
-      memset(expanded_log_file_path, 0, sizeof(expanded_log_file_path));
+    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
+/// @return FILE* decided by log_path_init() or stderr in case of error
-///         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 "
+                 "Logging to stderr, failed to open $" LOG_FILE_ENV ": %s",
-                 "caused by attempting to LOG() before initialization "
+                 log_file_path);
-                 "functions are called (e.g. init_homedir()).");
   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);
 

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
+#define LOG(level, ...) do_log((level), __func__, __LINE__, true, \
+                               __VA_ARGS__)
 
-#  if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
+#if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL
-#    undef DLOG
+# undef DLOG
-#    undef DLOGN
+# undef DLOGN
-#    define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \
+# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
+                          __VA_ARGS__)
-#    define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \
+# define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
+                           __VA_ARGS__)
-#  endif
+#endif
 
-#  if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
+#if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
-#    undef ILOG
+# undef ILOG
-#    undef ILOGN
+# undef ILOGN
-#    define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \
+# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
+                          __VA_ARGS__)
-#    define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \
+# define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
+                           __VA_ARGS__)
-#  endif
+#endif
 
-#  if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL
+#if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL
-#    undef WLOG
+# undef WLOG
-#    undef WLOGN
+# undef WLOGN
-#    define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \
+# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \
-       __VA_ARGS__)
+                          __VA_ARGS__)
-#    define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \
+# define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \
-       __VA_ARGS__)
+                           __VA_ARGS__)
-#  endif
+#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 <= 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

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.

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;

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;
   }

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);

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

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

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

test/README.md

@@ -2,6 +2,8 @@
 
 Tests are run by `/cmake/RunTests.cmake` file, using busted.
 
+For some failures, `.nvimlog` (or `$NVIM_LOG_FILE`) may provide insight.
+
 ## Directory structure
 
 Directories with tests: `/test/benchmark` for benchmarks, `/test/functional` for 

test/functional/helpers.lua

@@ -174,7 +174,7 @@ local os_name = (function()
 end)()
 
 local function iswin()
-  return os_name() == 'windows'
+  return package.config:sub(1,1) == '\\'
 end
 
 -- Executes a VimL function.

test/functional/options/defaults_spec.lua

@@ -8,6 +8,8 @@ local clear = helpers.clear
 local eval = helpers.eval
 local eq = helpers.eq
 local neq = helpers.neq
+local mkdir = helpers.mkdir
+local rmdir = helpers.rmdir
 
 local function init_session(...)
   local args = { helpers.nvim_prog, '-i', 'NONE', '--embed',
@@ -121,6 +123,56 @@ describe('startup defaults', function()
   it('v:progpath is set to the absolute path', function()
     eq(eval("fnamemodify(v:progpath, ':p')"), eval('v:progpath'))
   end)
+
+  describe('$NVIM_LOG_FILE', function()
+    -- TODO(jkeyes): use stdpath('data') instead.
+    local datasubdir = helpers.iswin() and 'nvim-data' or 'nvim'
+    local xdgdir = 'Xtest-startup-xdg-logpath'
+    local xdgdatadir = xdgdir..'/'..datasubdir
+    after_each(function()
+      os.remove('Xtest-logpath')
+      rmdir(xdgdir)
+    end)
+
+    it('is used if expansion succeeds', function()
+      clear({env={
+        NVIM_LOG_FILE='Xtest-logpath',
+      }})
+      eq('Xtest-logpath', eval('$NVIM_LOG_FILE'))
+    end)
+    it('defaults to stdpath("data")/log if empty', function()
+      eq(true, mkdir(xdgdir) and mkdir(xdgdatadir))
+      clear({env={
+        XDG_DATA_HOME=xdgdir,
+        NVIM_LOG_FILE='',  -- Empty is invalid.
+      }})
+      -- server_start() calls ELOG, which tickles log_path_init().
+      pcall(command, 'call serverstart(serverlist()[0])')
+
+      eq(xdgdir..'/'..datasubdir..'/log', string.gsub(eval('$NVIM_LOG_FILE'), '\\', '/'))
+    end)
+    it('defaults to stdpath("data")/log if invalid', function()
+      eq(true, mkdir(xdgdir) and mkdir(xdgdatadir))
+      clear({env={
+        XDG_DATA_HOME=xdgdir,
+        NVIM_LOG_FILE='.',  -- Any directory is invalid.
+      }})
+      -- server_start() calls ELOG, which tickles log_path_init().
+      pcall(command, 'call serverstart(serverlist()[0])')
+
+      eq(xdgdir..'/'..datasubdir..'/log', string.gsub(eval('$NVIM_LOG_FILE'), '\\', '/'))
+    end)
+    it('defaults to .nvimlog if stdpath("data") is invalid', function()
+      clear({env={
+        XDG_DATA_HOME='Xtest-missing-xdg-dir',
+        NVIM_LOG_FILE='.',  -- Any directory is invalid.
+      }})
+      -- server_start() calls ELOG, which tickles log_path_init().
+      pcall(command, 'call serverstart(serverlist()[0])')
+
+      eq('.nvimlog', eval('$NVIM_LOG_FILE'))
+    end)
+  end)
 end)
 
 describe('XDG-based defaults', function()