log: Always enable; remove DISABLE_LOG

- Establish ERROR log level as "critical". Such errors are rare and will
  be valuable when users encounter unusual circumstances.
- Set -DMIN_LOG_LEVEL=3 for release-type builds

.travis.yml

@@ -27,8 +27,7 @@ env:
                    -DCMAKE_INSTALL_PREFIX:PATH=$INSTALL_PREFIX
                    -DBUSTED_OUTPUT_TYPE=nvim
                    -DDEPS_PREFIX=$DEPS_BUILD_DIR/usr
-                   -DMIN_LOG_LEVEL=3
-                   -DDISABLE_LOG=1"
+                   -DMIN_LOG_LEVEL=3"
     - 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.
-if(NOT CMAKE_C_FLAGS_RELEASE MATCHES DDISABLE_LOG)
-  set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} -DDISABLE_LOG")
+# Minimize logging for release-type builds.
+if(NOT CMAKE_C_FLAGS_RELEASE MATCHES DMIN_LOG_LEVEL)
+  set(CMAKE_C_FLAGS_RELEASE "${CMAKE_C_FLAGS_RELEASE} -DMIN_LOG_LEVEL=3")
 endif()
-if(NOT CMAKE_C_FLAGS_MINSIZEREL MATCHES DDISABLE_LOG)
-  set(CMAKE_C_FLAGS_MINSIZEREL "${CMAKE_C_FLAGS_MINSIZEREL} -DDISABLE_LOG")
+if(NOT CMAKE_C_FLAGS_MINSIZEREL MATCHES DMIN_LOG_LEVEL)
+  set(CMAKE_C_FLAGS_MINSIZEREL "${CMAKE_C_FLAGS_MINSIZEREL} -DMIN_LOG_LEVEL=3")
 endif()
-if(NOT CMAKE_C_FLAGS_RELWITHDEBINFO MATCHES DDISABLE_LOG)
-  set(CMAKE_C_FLAGS_RELWITHDEBINFO "${CMAKE_C_FLAGS_RELWITHDEBINFO} -DDISABLE_LOG")
+if(NOT CMAKE_C_FLAGS_RELWITHDEBINFO MATCHES DMIN_LOG_LEVEL)
+  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.

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
-# "Release", in which case logging is disabled).
-# The log level must be a number DEBUG (0), INFO (1), WARNING (2) or ERROR (3).
+# The default log level is 1 (INFO) (unless CMAKE_BUILD_TYPE is "Release").
+# Log levels: 0 (DEBUG), 1 (INFO), 2 (WARNING), 3 (ERROR)
 # CMAKE_EXTRA_FLAGS += -DMIN_LOG_LEVEL=1
 
 # By default, nvim uses bundled versions of its required third-party

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

@@ -14361,7 +14361,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/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 in garray(%d), should be %d", item_size);
   }
   ga_grow(gap, 1);
   return ((char *)gap->ga_data) + (item_size * (size_t)gap->ga_len++);

src/nvim/log.c

@@ -76,6 +76,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();
@@ -124,11 +128,10 @@ end:
 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;
   }
 
@@ -145,9 +148,8 @@ FILE *open_log_file(void)
   }
 
   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()).");
+                 "Cannot open " USR_LOG_FILE ", logging to stderr. Was LOG()"
+                 " called before early_init()?");
   return stderr;
 }
 
@@ -172,7 +174,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 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
+#endif
 
-#  if MIN_LOG_LEVEL <= INFO_LOG_LEVEL
+#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
+#endif
 
-#  if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL
+#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
+#endif
 
-#  if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL
+#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
-
 #endif
 
 #ifdef INCLUDE_GENERATED_DECLARATIONS

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