aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--runtime/doc/starting.txt2
-rw-r--r--src/nvim/README.md2
-rw-r--r--src/nvim/channel.c2
-rw-r--r--src/nvim/generators/gen_api_dispatch.lua4
-rw-r--r--src/nvim/globals.h5
-rw-r--r--src/nvim/log.c66
-rw-r--r--src/nvim/log.h47
-rw-r--r--src/nvim/msgpack_rpc/channel.c14
-rw-r--r--src/nvim/state.c4
-rw-r--r--src/nvim/ui.c6
-rw-r--r--test/functional/core/startup_spec.lua1
11 files changed, 87 insertions, 66 deletions
diff --git a/runtime/doc/starting.txt b/runtime/doc/starting.txt
index 8b88fa9363..4a88939715 100644
--- a/runtime/doc/starting.txt
+++ b/runtime/doc/starting.txt
@@ -1349,7 +1349,7 @@ STATE DIRECTORY (DEFAULT) ~
Note: Throughout the user manual these defaults are used as placeholders, e.g.
"~/.config" is understood to mean "$XDG_CONFIG_HOME or ~/.config".
-LOG FILE *$NVIM_LOG_FILE*
+LOG FILE *$NVIM_LOG_FILE* *E5430*
Besides 'debug' and 'verbose', Nvim keeps a general log file for internal
debugging, plugins and RPC clients. >
:echo $NVIM_LOG_FILE
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)); \
} \
diff --git a/test/functional/core/startup_spec.lua b/test/functional/core/startup_spec.lua
index f87fd8e951..18d48efadc 100644
--- a/test/functional/core/startup_spec.lua
+++ b/test/functional/core/startup_spec.lua
@@ -255,6 +255,7 @@ describe('startup', function()
it('does not crash when expanding cdpath during early_init', function()
clear{env={CDPATH='~doesnotexist'}}
+ assert_alive()
eq(',~doesnotexist', eval('&cdpath'))
end)
generated by cgit (git 2.34.1) at 2025-04-28 23:57:56 +0000