mirrors/neovim
1
0
Fork 0
mirror of https://github.com/neovim/neovim.git synced 2025-09-06 03:18:16 +00:00
Code Issues Packages Projects Releases Wiki Activity

fix(logging): skip recursion, fix crash #18764

Browse Source 
Problem:
1. The main log routine does not protect itself against recursion.
   log_lock() doesn't guard against recursion, it would deadlock...
2. 22b52dd462 (#11501) regressed 6f27f5ef91 (#10172), because
   set_init_1..process_spawn tries to log (see backtrace below), but the
   mutex isn't initialized yet. Even if the mutex were valid, we don't
   want early logging to fallback to stderr because that can break
   embedders when stdio is used for RPC.

    frame 1: 0x00000001001d54f4 nvim`open_log_file at log.c:205:7
    frame 2: 0x00000001001d5390 nvim`logmsg(log_level=1, context="UI: ", func_name=0x0000000000000000, line_num=-1, eol=true, fmt="win_viewport") at log.c:150:20
    frame : 0x000000010039aea2 nvim`ui_call_win_viewport(grid=2, win=1000, topline=0, botline=1, curline=0, curcol=0, line_count=1) at ui_events_call.generated.h:321:3
    frame 4: 0x00000001003dfefc nvim`ui_ext_win_viewport(wp=0x0000000101816400) at window.c:939:5
    frame 5: 0x00000001003ec5b4 nvim`win_ui_flush at window.c:7303:7
    frame 6: 0x00000001003a04c0 nvim`ui_flush at ui.c:508:3
    frame 7: 0x00000001002966ba nvim`do_os_system(argv=0x0000600000c0c000, input=0x0000000000000000, len=0, output=0x0000000000000000, nread=0x00007ff7bfefe830, silent=false, forward_output=false) at shell.c:894:3
    frame 8: 0x0000000100295f68 nvim`os_call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_args=0x0000000000000000) at shell.c:663:18
    frame 9: 0x0000000100295845 nvim`call_shell(cmd="unset nonomatch; vimglob() { while [ $# -ge 1 ]; do echo \"$1\"; shift; done }; vimglob >/var/folders/gk/3tttv_md06987tlwpyp62jrw0000gn/T/nvimwwvwfD/0 ~foo", opts=kShellOptExpand | kShellOptSilent | kShellOptHideMess, extra_shell_arg=0x0000000000000000) at shell.c:712:14
    frame 10: 0x0000000100294c6f nvim`os_expand_wildcards(num_pat=1, pat=0x00007ff7bfefeb20, num_file=0x00007ff7bfefee58, file=0x00007ff7bfefee60, flags=43) at shell.c:328:7
    ...
    frame 23: 0x000000010028ccef nvim`expand_env_esc(srcp=",~foo", dst="~foo", dstlen=4094, esc=false, one=false, prefix=0x0000000000000000) at env.c:673:17
    frame 24: 0x000000010026fdd5 nvim`option_expand(opt_idx=29, val=",~foo") at option.c:1950:3
    frame 25: 0x000000010026f129 nvim`set_init_1(clean_arg=false) at option.c:558:19
    frame 26: 0x00000001001ea25e nvim`early_init(paramp=0x00007ff7bfeff5f0) at main.c:198:3
    frame 27: 0x00000001001ea6bf nvim`main(argc=1, argv=0x00007ff7bfeff848) at main.c:255:3

Solution:
1. Check for recursion, show "internal error" message.
    - FUTURE: when "remote TUI" is merged, can we remove log_lock()?
2. Skip logging if log_init wasn't called yet.
This commit is contained in:
Justin M. Keyes
2022-05-30 22:07:33 +02:00
committed by GitHub
parent 8427da9299
commit f6e19e7334
11 changed files with 87 additions and 66 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
runtime/doc/starting.txt
View File

@@ -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

2
src/nvim/README.md
View File

@@ -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"

2
src/nvim/channel.c
View File

@@ -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) {

4
src/nvim/generators/gen_api_dispatch.lua
View File

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

5
src/nvim/globals.h
View File

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

66
src/nvim/log.c
View File

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

47
src/nvim/log.h
View File

@@ -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

14
src/nvim/msgpack_rpc/channel.c
View File

@@ -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] "

4
src/nvim/state.c
View File

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

6
src/nvim/ui.c
View File

@@ -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)); \
} \

1
test/functional/core/startup_spec.lua
View File

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