Merge pull request #22415 from bfredl/log_debug

refactor(log): reduce compile time LOG_LEVEL granularity

CMakeLists.txt

@@ -135,6 +135,7 @@ endif()
 option(LOG_LIST_ACTIONS "Add list actions logging" OFF)
 
 option(CLANG_ASAN_UBSAN "Enable Clang address & undefined behavior sanitizer for nvim binary." OFF)
+option(LOG_DEBUG "Enable debug log messages even in a release build" OFF)
 option(CLANG_MSAN "Enable Clang memory sanitizer for nvim binary." OFF)
 option(CLANG_TSAN "Enable Clang thread sanitizer for nvim binary." OFF)
 

contrib/flake.nix

@@ -33,7 +33,6 @@
           NIX_CFLAGS_COMPILE = " -ggdb -Og";
 
           cmakeBuildType = "Debug";
-          cmakeFlags = oa.cmakeFlags ++ [ "-DMIN_LOG_LEVEL=0" ];
 
           disallowedReferences = [ ];
         });
@@ -45,7 +44,6 @@
         }).overrideAttrs (oa: {
           cmakeFlags = oa.cmakeFlags ++ [
             "-DLUACHECK_PRG=${luacheck}/bin/luacheck"
-            "-DMIN_LOG_LEVEL=0"
             "-DENABLE_LTO=OFF"
           ] ++ final.lib.optionals final.stdenv.isLinux [
             # https://github.com/google/sanitizers/wiki/AddressSanitizerFlags

contrib/local.mk.example

@@ -31,9 +31,10 @@
 # often.  You can disable it explicitly:
 # CMAKE_EXTRA_FLAGS += -DENABLE_LTO=OFF
 
-# Log levels: 0 (DEBUG), 1 (INFO), 2 (WARNING), 3 (ERROR)
+# Log levels: DEBUG, INFO, WARNING, ERROR
-# Default is 1 (INFO) unless CMAKE_BUILD_TYPE is Release or RelWithDebInfo.
+# For Debug builds all log levels are used
-# CMAKE_EXTRA_FLAGS += -DMIN_LOG_LEVEL=1
+# For Release and RelWithDebInfo builds only WARNING and ERROR are used, unless:
+# CMAKE_EXTRA_FLAGS += -DLOG_DEBUG
 
 # By default, nvim uses bundled versions of its required third-party
 # dependencies.

src/nvim/CMakeLists.txt

@@ -373,19 +373,16 @@ else()
     ${EXTERNAL_SOURCES} PROPERTIES COMPILE_FLAGS "${COMPILE_FLAGS} -Wno-conversion -Wno-missing-noreturn -Wno-missing-format-attribute -Wno-double-promotion -Wno-strict-prototypes -Wno-misleading-indentation")
 endif()
 
-# Log level (MIN_LOG_LEVEL in log.h)
+# Log level (NVIM_LOG_DEBUG in log.h)
 if($ENV{CI})
-  set(MIN_LOG_LEVEL 3)
+  # Don't debug log on CI, it gets too verbose in the main build log.
-endif()
+  # TODO(bfredl): debug log level also exposes some errors with EXITFREE in ASAN build.
-if("${MIN_LOG_LEVEL}" MATCHES "^$")
+  set(LOG_DEBUG FALSE)
-  # Minimize logging for release-type builds.
+elseif(LOG_DEBUG)
-  target_compile_definitions(main_lib INTERFACE MIN_LOG_LEVEL=$<IF:$<CONFIG:Debug>,1,3>)
+  target_compile_definitions(nvim PRIVATE NVIM_LOG_DEBUG)
 else()
-  if(NOT MIN_LOG_LEVEL MATCHES "^[0-3]$")
+  # Minimize logging for release-type builds.
-    message(FATAL_ERROR "invalid MIN_LOG_LEVEL: " ${MIN_LOG_LEVEL})
+  target_compile_definitions(nvim PRIVATE $<$<CONFIG:Debug>:NVIM_LOG_DEBUG>)
-  endif()
-  message(STATUS "MIN_LOG_LEVEL=${MIN_LOG_LEVEL}")
-  target_compile_definitions(main_lib INTERFACE MIN_LOG_LEVEL=${MIN_LOG_LEVEL})
 endif()
 
 if(CLANG_ASAN_UBSAN OR CLANG_MSAN OR CLANG_TSAN)

src/nvim/README.md

@@ -29,17 +29,17 @@ Logs
 
 Low-level log messages sink to `$NVIM_LOG_FILE`.
 
-UI events are logged at DEBUG level (`LOGLVL_DBG`).
+UI events are logged at DEBUG level.
 
     rm -rf build/
-    make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0"
+    make CMAKE_EXTRA_FLAGS="-DLOG_DEBUG"
 
 Use `LOG_CALLSTACK()` (Linux only) to log the current stacktrace. To log to an
 alternate file (e.g. stderr) use `LOG_CALLSTACK_TO_FILE(FILE*)`. Requires
 `-no-pie` ([ref](https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=860394#15)):
 
     rm -rf build/
-    make CMAKE_EXTRA_FLAGS="-DMIN_LOG_LEVEL=0 -DCMAKE_C_FLAGS=-no-pie"
+    make CMAKE_EXTRA_FLAGS="-DLOG_DEBUG -DCMAKE_C_FLAGS=-no-pie"
 
 Many log messages have a shared prefix, such as "UI" or "RPC". Use the shell to
 filter the log, e.g. at DEBUG level you might want to exclude UI messages:

src/nvim/channel.c

@@ -209,7 +209,7 @@ Channel *channel_alloc(ChannelStreamType type)
 
 void channel_create_event(Channel *chan, const char *ext_source)
 {
-#if MIN_LOG_LEVEL <= LOGLVL_INF
+#ifdef NVIM_LOG_DEBUG
   const char *source;
 
   if (ext_source) {

src/nvim/generators/gen_api_dispatch.lua

@@ -257,9 +257,8 @@ for i = 1, #functions do
 
     output:write('Object handle_'..fn.name..'(uint64_t channel_id, Array args, Arena* arena, Error *error)')
     output:write('\n{')
-    output:write('\n#if MIN_LOG_LEVEL <= LOGLVL_DBG')
+    output:write('\n#ifdef NVIM_LOG_DEBUG')
-    output:write('\n  logmsg(LOGLVL_DBG, "RPC: ", NULL, -1, true, "ch %" PRIu64 ": invoke '
+    output:write('\n  DLOG("RPC: ch %" PRIu64 ": invoke '..fn.name..'", channel_id);')
-                 ..fn.name..'", channel_id);')
     output:write('\n#endif')
     output:write('\n  Object ret = NIL;')
     -- Declare/initialize variables that will hold converted arguments

src/nvim/keycodes.c

@@ -1095,15 +1095,3 @@ void vim_unescape_ks(char *p)
   }
   *d = NUL;
 }
-
-/// Logs a single key as a human-readable keycode.
-void log_key(int log_level, int key)
-{
-  if (log_level < MIN_LOG_LEVEL) {
-    return;
-  }
-  char *keyname = key == K_EVENT
-    ? "K_EVENT"
-    : (char *)get_special_key_name(key, mod_mask);
-  LOG(log_level, "input: %s", keyname);
-}

src/nvim/log.c

@@ -141,9 +141,13 @@ bool logmsg(int log_level, const char *context, const char *func_name, int line_
     return false;
   }
 
-  if (log_level < MIN_LOG_LEVEL) {
+#ifndef NVIM_LOG_DEBUG
+  // This should rarely happen (callsites are compiled out), but to be sure.
+  // TODO(bfredl): allow log levels to be configured at runtime
+  if (log_level < LOGLVL_WRN) {
     return false;
   }
+#endif
 
 #ifdef EXITFREE
   // Logging after we've already started freeing all our memory will only cause

src/nvim/log.h

@@ -17,54 +17,29 @@
 # define NVIM_PROBE(name, n, ...)
 #endif
 
-#define LOGLVL_TRC 0
 #define LOGLVL_DBG 1
 #define LOGLVL_INF 2
 #define LOGLVL_WRN 3
 #define LOGLVL_ERR 4
 
-#define DLOG(...)
-#define DLOGN(...)
-#define ILOG(...)
-#define ILOGN(...)
-#define WLOG(...)
-#define WLOGN(...)
-#define ELOG(...)
-#define ELOGN(...)
-
-#ifndef MIN_LOG_LEVEL
-# define MIN_LOG_LEVEL LOGLVL_INF
-#endif
-
 #define LOG(level, ...) logmsg((level), NULL, __func__, __LINE__, true, __VA_ARGS__)
 
-#if MIN_LOG_LEVEL <= LOGLVL_DBG
+#ifdef NVIM_LOG_DEBUG
-# undef DLOG
-# undef DLOGN
 # 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 <= LOGLVL_INF
-# undef ILOG
-# undef ILOGN
 # define ILOG(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, true, __VA_ARGS__)
 # define ILOGN(...) logmsg(LOGLVL_INF, NULL, __func__, __LINE__, false, __VA_ARGS__)
+#else
+# define DLOG(...)
+# define DLOGN(...)
+# define ILOG(...)
+# define ILOGN(...)
 #endif
 
-#if MIN_LOG_LEVEL <= LOGLVL_WRN
+#define WLOG(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, true, __VA_ARGS__)
-# undef WLOG
+#define WLOGN(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, false, __VA_ARGS__)
-# undef WLOGN
+#define ELOG(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, true, __VA_ARGS__)
-# define WLOG(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, true, __VA_ARGS__)
+#define ELOGN(...) logmsg(LOGLVL_ERR, NULL, __func__, __LINE__, false, __VA_ARGS__)
-# define WLOGN(...) logmsg(LOGLVL_WRN, NULL, __func__, __LINE__, false, __VA_ARGS__)
-#endif
-
-#if MIN_LOG_LEVEL <= LOGLVL_ERR
-# undef ELOG
-# undef ELOGN
-# 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
 # define LOG_CALLSTACK() log_callstack(__func__, __LINE__)

src/nvim/msgpack_rpc/channel.c

@@ -39,7 +39,73 @@
 #include "nvim/ui.h"
 #include "nvim/ui_client.h"
 
-#if MIN_LOG_LEVEL > LOGLVL_DBG
+#ifdef NVIM_LOG_DEBUG
+# define REQ "[request]  "
+# define RES "[response] "
+# define NOT "[notify]   "
+# define ERR "[error]    "
+
+// Cannot define array with negative offsets, so this one is needed to be added
+// to MSGPACK_UNPACK_\* values.
+# define MUR_OFF 2
+
+static const char *const msgpack_error_messages[] = {
+  [MSGPACK_UNPACK_EXTRA_BYTES + MUR_OFF] = "extra bytes found",
+  [MSGPACK_UNPACK_CONTINUE + MUR_OFF] = "incomplete string",
+  [MSGPACK_UNPACK_PARSE_ERROR + MUR_OFF] = "parse error",
+  [MSGPACK_UNPACK_NOMEM_ERROR + MUR_OFF] = "not enough memory",
+};
+
+static void log_close(FILE *f)
+{
+  fputc('\n', f);
+  fflush(f);
+  fclose(f);
+  log_unlock();
+}
+
+static void log_server_msg(uint64_t channel_id, msgpack_sbuffer *packed)
+{
+  msgpack_unpacked unpacked;
+  msgpack_unpacked_init(&unpacked);
+  DLOGN("RPC ->ch %" PRIu64 ": ", channel_id);
+  const msgpack_unpack_return result =
+    msgpack_unpack_next(&unpacked, packed->data, packed->size, NULL);
+  switch (result) {
+  case MSGPACK_UNPACK_SUCCESS: {
+    uint64_t type = unpacked.data.via.array.ptr[0].via.u64;
+    log_lock();
+    FILE *f = open_log_file();
+    fprintf(f, type ? (type == 1 ? RES : NOT) : REQ);
+    msgpack_object_print(f, unpacked.data);
+    log_close(f);
+    msgpack_unpacked_destroy(&unpacked);
+    break;
+  }
+  case MSGPACK_UNPACK_EXTRA_BYTES:
+  case MSGPACK_UNPACK_CONTINUE:
+  case MSGPACK_UNPACK_PARSE_ERROR:
+  case MSGPACK_UNPACK_NOMEM_ERROR: {
+    log_lock();
+    FILE *f = open_log_file();
+    fprintf(f, ERR);
+    fprintf(f, "%s", msgpack_error_messages[result + MUR_OFF]);
+    log_close(f);
+    break;
+  }
+  }
+}
+
+static void log_client_msg(uint64_t channel_id, bool is_request, const char *name)
+{
+  DLOGN("RPC <-ch %" PRIu64 ": ", channel_id);
+  log_lock();
+  FILE *f = open_log_file();
+  fprintf(f, "%s: %s", is_request ? REQ : RES, name);
+  log_close(f);
+}
+
+#else
 # define log_client_msg(...)
 # define log_server_msg(...)
 #endif
@@ -71,7 +137,7 @@ void rpc_start(Channel *channel)
 
   if (channel->streamtype != kChannelStreamInternal) {
     Stream *out = channel_outstream(channel);
-#if MIN_LOG_LEVEL <= LOGLVL_DBG
+#ifdef NVIM_LOG_DEBUG
     Stream *in = channel_instream(channel);
     DLOG("rpc ch %" PRIu64 " in-stream=%p out-stream=%p", channel->id,
          (void *)in, (void *)out);
@@ -668,70 +734,3 @@ const char *rpc_client_name(Channel *chan)
 
   return NULL;
 }
-
-#if MIN_LOG_LEVEL <= LOGLVL_DBG
-# define REQ "[request]  "
-# define RES "[response] "
-# define NOT "[notify]   "
-# define ERR "[error]    "
-
-// Cannot define array with negative offsets, so this one is needed to be added
-// to MSGPACK_UNPACK_\* values.
-# define MUR_OFF 2
-
-static const char *const msgpack_error_messages[] = {
-  [MSGPACK_UNPACK_EXTRA_BYTES + MUR_OFF] = "extra bytes found",
-  [MSGPACK_UNPACK_CONTINUE + MUR_OFF] = "incomplete string",
-  [MSGPACK_UNPACK_PARSE_ERROR + MUR_OFF] = "parse error",
-  [MSGPACK_UNPACK_NOMEM_ERROR + MUR_OFF] = "not enough memory",
-};
-
-static void log_server_msg(uint64_t channel_id, msgpack_sbuffer *packed)
-{
-  msgpack_unpacked unpacked;
-  msgpack_unpacked_init(&unpacked);
-  DLOGN("RPC ->ch %" PRIu64 ": ", channel_id);
-  const msgpack_unpack_return result =
-    msgpack_unpack_next(&unpacked, packed->data, packed->size, NULL);
-  switch (result) {
-  case MSGPACK_UNPACK_SUCCESS: {
-    uint64_t type = unpacked.data.via.array.ptr[0].via.u64;
-    log_lock();
-    FILE *f = open_log_file();
-    fprintf(f, type ? (type == 1 ? RES : NOT) : REQ);
-    msgpack_object_print(f, unpacked.data);
-    log_close(f);
-    msgpack_unpacked_destroy(&unpacked);
-    break;
-  }
-  case MSGPACK_UNPACK_EXTRA_BYTES:
-  case MSGPACK_UNPACK_CONTINUE:
-  case MSGPACK_UNPACK_PARSE_ERROR:
-  case MSGPACK_UNPACK_NOMEM_ERROR: {
-    log_lock();
-    FILE *f = open_log_file();
-    fprintf(f, ERR);
-    fprintf(f, "%s", msgpack_error_messages[result + MUR_OFF]);
-    log_close(f);
-    break;
-  }
-  }
-}
-
-static void log_client_msg(uint64_t channel_id, bool is_request, const char *name)
-{
-  DLOGN("RPC <-ch %" PRIu64 ": ", channel_id);
-  log_lock();
-  FILE *f = open_log_file();
-  fprintf(f, "%s: %s", is_request ? REQ : RES, name);
-  log_close(f);
-}
-
-static void log_close(FILE *f)
-{
-  fputc('\n', f);
-  fflush(f);
-  fclose(f);
-  log_unlock();
-}
-#endif

src/nvim/state.c

@@ -92,8 +92,9 @@ getkey:
       may_sync_undo();
     }
 
-#if MIN_LOG_LEVEL <= LOGLVL_DBG
+#ifdef NVIM_LOG_DEBUG
-    log_key(LOGLVL_DBG, key);
+    char *keyname = key == K_EVENT ? "K_EVENT" : (char *)get_special_key_name(key, mod_mask);
+    DLOG("input: %s", keyname);
 #endif
 
     int execute_result = s->execute(s, key);

src/nvim/ui.c

@@ -63,9 +63,7 @@ static int pending_has_mouse = -1;
 
 static Array call_buf = ARRAY_DICT_INIT;
 
-#if MIN_LOG_LEVEL > LOGLVL_DBG
+#ifdef NVIM_LOG_DEBUG
-# define ui_log(funname)
-#else
 static size_t uilog_seen = 0;
 static const char *uilog_last_event = NULL;
 
@@ -89,6 +87,8 @@ static void ui_log(const char *funname)
     uilog_last_event = funname;
   }
 }
+#else
+# define ui_log(funname)
 #endif
 
 // UI_CALL invokes a function on all registered UI instances.

test/symbolic/klee/run.sh

@@ -58,7 +58,6 @@ main() {
   includes="$includes -I/host-includes"
 
   local defines=
-  defines="$defines -DMIN_LOG_LEVEL=9999"
   defines="$defines -DINCLUDE_GENERATED_DECLARATIONS"
 
   test -z "$compile" && defines="$defines -DUSE_KLEE"