From eb2473e9ea0a875b79612f84d1fae32b670d9b88 Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Sun, 23 Jul 2017 17:00:30 +0200 Subject: log: log_callstack() --- src/nvim/log.c | 47 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index f1dbe61dda..252fe5438d 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -173,6 +173,53 @@ FILE *open_log_file(void) return stderr; } +#if defined(__linux__) +# include +void log_callstack(const char *const func_name, const int line_num) +{ + void *trace[100]; + int trace_size = backtrace(trace, ARRAY_SIZE(trace)); + + char exepath[MAXPATHL] = { 0 }; + size_t exepathlen = MAXPATHL; + if (os_exepath(exepath, &exepathlen) != 0) { + abort(); + } + assert(24 + exepathlen < IOSIZE); // Must fit in `cmdbuf` below. + + do_log(DEBUG_LOG_LEVEL, func_name, line_num, true, "trace:"); + + char cmdbuf[IOSIZE + (20 * ARRAY_SIZE(trace))]; + snprintf(cmdbuf, sizeof(cmdbuf), "addr2line -e %s -f -p", exepath); + for (int i = 1; i < trace_size; i++) { + char buf[20]; // 64-bit pointer 0xNNNNNNNNNNNNNNNN with leading space. + snprintf(buf, sizeof(buf), " %p", trace[i]); + xstrlcat(cmdbuf, buf, sizeof(cmdbuf)); + } + // Now we have a command string like: + // addr2line -e /path/to/exe -f -p 0x123 0x456 ... + + log_lock(); + FILE *log_file = open_log_file(); + if (log_file == NULL) { + goto end; + } + + FILE *fp = popen(cmdbuf, "r"); + char linebuf[IOSIZE]; + while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) { + fprintf(log_file, " %s", linebuf); + } + pclose(fp); + + if (log_file != stderr && log_file != stdout) { + fclose(log_file); + } +end: + log_unlock(); +} +#endif + static bool do_log_to_file(FILE *log_file, int log_level, const char *func_name, int line_num, bool eol, const char* fmt, ...) -- cgit From a7538371fec595641bed2d5e2d92e5ae2ce89b94 Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Sun, 30 Jul 2017 23:02:41 +0200 Subject: build: linux does not always have execinfo.h (#7101) Closes #7099 --- src/nvim/log.c | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index 252fe5438d..b64aef3cac 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -25,6 +25,10 @@ static uv_mutex_t mutex; # include "log.c.generated.h" #endif +#ifdef HAVE_EXECINFO_BACKTRACE +# include +#endif + static bool log_try_create(char *fname) { if (fname == NULL || fname[0] == '\0') { @@ -173,8 +177,7 @@ FILE *open_log_file(void) return stderr; } -#if defined(__linux__) -# include +#ifdef HAVE_EXECINFO_BACKTRACE void log_callstack(const char *const func_name, const int line_num) { void *trace[100]; -- cgit From 17eb20b22ef9fe5e621a4b6eff1c1a83e9489645 Mon Sep 17 00:00:00 2001 From: James McCoy Date: Wed, 9 Aug 2017 13:30:34 -0400 Subject: log: Add log_callstack_to_file() This makes it trivial to log the callstack to, e.g., stderr, which can simplify debug cycles. --- src/nvim/log.c | 25 ++++++++++++++++--------- 1 file changed, 16 insertions(+), 9 deletions(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index b64aef3cac..3baf0b2ebd 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -178,7 +178,8 @@ FILE *open_log_file(void) } #ifdef HAVE_EXECINFO_BACKTRACE -void log_callstack(const char *const func_name, const int line_num) +void log_callstack_to_file(FILE *log_file, const char *const func_name, + const int line_num) { void *trace[100]; int trace_size = backtrace(trace, ARRAY_SIZE(trace)); @@ -190,8 +191,6 @@ void log_callstack(const char *const func_name, const int line_num) } assert(24 + exepathlen < IOSIZE); // Must fit in `cmdbuf` below. - do_log(DEBUG_LOG_LEVEL, func_name, line_num, true, "trace:"); - char cmdbuf[IOSIZE + (20 * ARRAY_SIZE(trace))]; snprintf(cmdbuf, sizeof(cmdbuf), "addr2line -e %s -f -p", exepath); for (int i = 1; i < trace_size; i++) { @@ -202,12 +201,8 @@ void log_callstack(const char *const func_name, const int line_num) // Now we have a command string like: // addr2line -e /path/to/exe -f -p 0x123 0x456 ... - log_lock(); - FILE *log_file = open_log_file(); - if (log_file == NULL) { - goto end; - } - + do_log_to_file(log_file, DEBUG_LOG_LEVEL, func_name, line_num, true, + "trace:"); FILE *fp = popen(cmdbuf, "r"); char linebuf[IOSIZE]; while (fgets(linebuf, sizeof(linebuf) - 1, fp) != NULL) { @@ -218,6 +213,18 @@ void log_callstack(const char *const func_name, const int line_num) if (log_file != stderr && log_file != stdout) { fclose(log_file); } +} + +void log_callstack(const char *const func_name, const int line_num) +{ + log_lock(); + FILE *log_file = open_log_file(); + if (log_file == NULL) { + goto end; + } + + log_callstack_to_file(log_file, func_name, line_num); + end: log_unlock(); } -- cgit From af993da4351d579aa24de08d806c8c1b90813106 Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Thu, 27 Jul 2017 01:08:50 +0200 Subject: rpc: close channel if stream was closed f_jobstop()/f_rpcstop() .. process_stop() .. process_close_in(proc) closes the write-stream of a RPC channel. But there might be a pending RPC notification on the queue, which may get processed just before the channel is closed. To handle that case, check the Stream.closed in channel.c:receive_msgpack(). Before this change, the above scenario could trigger this assert(!stream->closed) in wstream_write(): 0x00007f96e1cd3428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54 0x00007f96e1cd502a in __GI_abort () at abort.c:89 0x00007f96e1ccbbd7 in __assert_fail_base (fmt=, assertion=assertion@entry=0x768f9b "!stream->closed", file=file@entry=0x768f70 "../src/nvim/event/wstream.c", line=line@entry=77, function=function@entry=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:92 0x00007f96e1ccbc82 in __GI___assert_fail (assertion=0x768f9b "!stream->closed", file=0x768f70 "../src/nvim/event/wstream.c", line=77, function=0x768fb0 <__PRETTY_FUNCTION__.13735> "wstream_write") at assert.c:101 0x00000000004d2c1f in wstream_write (stream=0x7f96e0a35078, buffer=0x7f96e09f9b40) at ../src/nvim/event/wstream.c:77 0x00000000005857b2 in channel_write (channel=0x7f96e0ae5800, buffer=0x7f96e09f9b40) at ../src/nvim/msgpack_rpc/channel.c:551 0x000000000058567d in on_request_event (argv=0x7ffed792efa0) at ../src/nvim/msgpack_rpc/channel.c:523 0x00000000005854c8 in handle_request (channel=0x7f96e0ae5800, request=0x7ffed792f1b8) at ../src/nvim/msgpack_rpc/channel.c:503 0x00000000005850cb in parse_msgpack (channel=0x7f96e0ae5800) at ../src/nvim/msgpack_rpc/channel.c:423 0x0000000000584f90 in receive_msgpack (stream=0x7f96e0a35218, rbuf=0x7f96e0d1d4c0, c=22, data=0x7f96e0ae5800, eof=false) at ../src/nvim/msgpack_rpc/channel.c:389 0x00000000004d0b20 in read_event (argv=0x7ffed792f4a8) at ../src/nvim/event/rstream.c:190 0x00000000004ce462 in multiqueue_process_events (this=0x7f96e18172d0) at ../src/nvim/event/multiqueue.c:150 0x000000000059b630 in nv_event (cap=0x7ffed792f620) at ../src/nvim/normal.c:7908 0x000000000058be69 in normal_execute (state=0x7ffed792f580, key=-25341) at ../src/nvim/normal.c:1137 0x0000000000652463 in state_enter (s=0x7ffed792f580) at ../src/nvim/state.c:61 0x000000000058a1fe in normal_enter (cmdwin=false, noexmode=false) at ../src/nvim/normal.c:467 0x00000000005500c2 in main (argc=2, argv=0x7ffed792f8d8) at ../src/nvim/main.c:554 Alternative approach suggested by bfredl is to use close_cb of the process. My unsuccessful attempt is below. (It seems close_cb is queued too late, which is the similar problem addressed by this commit): commit 75fc12c6ab15711bdb7b18c6d42ec9d157f5145e Author: Justin M. Keyes Date: Fri Aug 18 01:30:41 2017 +0200 rpc: use Stream's close_cb instead of explicit check in receive_msgpack() diff --git a/src/nvim/event/process.c b/src/nvim/event/process.c index 8371d3cd482e..e52da23cdc40 100644 --- a/src/nvim/event/process.c +++ b/src/nvim/event/process.c @@ -416,6 +416,10 @@ static void on_process_exit(Process *proc) static void on_process_stream_close(Stream *stream, void *data) { Process *proc = data; + ILOG("on_process_stream_close"); + if (proc->stream_close_cb != NULL) { + proc->stream_close_cb(stream, proc->stream_close_data); + } decref(proc); } diff --git a/src/nvim/event/process.h b/src/nvim/event/process.h index 5c00e8e7ecd5..34a8d54f6f8c 100644 --- a/src/nvim/event/process.h +++ b/src/nvim/event/process.h @@ -26,6 +26,11 @@ struct process { Stream *in, *out, *err; process_exit_cb cb; internal_process_cb internal_exit_cb, internal_close_cb; + + // Called when any of the process streams (in/out/err) closes. + stream_close_cb stream_close_cb; + void *stream_close_data; + bool closed, detach; MultiQueue *events; }; @@ -50,6 +55,8 @@ static inline Process process_init(Loop *loop, ProcessType type, void *data) .closed = false, .internal_close_cb = NULL, .internal_exit_cb = NULL, + .stream_close_cb = NULL, + .stream_close_data = NULL, .detach = false }; } diff --git a/src/nvim/event/stream.c b/src/nvim/event/stream.c index 7c865bfe1e8c..c8720d1e45d9 100644 --- a/src/nvim/event/stream.c +++ b/src/nvim/event/stream.c @@ -95,7 +95,11 @@ void stream_close(Stream *stream, stream_close_cb on_stream_close, void *data) void stream_close_handle(Stream *stream) FUNC_ATTR_NONNULL_ALL { + ILOG("stream=%d", stream); + // LOG_CALLSTACK(); if (stream->uvstream) { + // problem: this schedules on the queue, but channel.c:receive_msgpack may + // be processed before close_cb is called by libuv. uv_close((uv_handle_t *)stream->uvstream, close_cb); } else { uv_close((uv_handle_t *)&stream->uv.idle, close_cb); @@ -105,6 +109,7 @@ void stream_close_handle(Stream *stream) static void close_cb(uv_handle_t *handle) { Stream *stream = handle->data; + ILOG(">>>>>>>>>>>>>>>>>>>>>>> stream=%p stream->internal_close_cb=%p", stream, stream->internal_close_cb); if (stream->buffer) { rbuffer_free(stream->buffer); } diff --git a/src/nvim/msgpack_rpc/channel.c b/src/nvim/msgpack_rpc/channel.c index 782eabe04e4a..dc2b794e366a 100644 --- a/src/nvim/msgpack_rpc/channel.c +++ b/src/nvim/msgpack_rpc/channel.c @@ -128,6 +128,8 @@ uint64_t channel_from_process(Process *proc, uint64_t id, char *source) source); incref(channel); // process channels are only closed by the exit_cb channel->data.proc = proc; + channel->data.proc->stream_close_cb = close_cb2; + channel->data.proc->stream_close_data = channel; wstream_init(proc->in, 0); rstream_init(proc->out, 0); @@ -387,17 +389,6 @@ static void receive_msgpack(Stream *stream, RBuffer *rbuf, size_t c, goto end; } - if ((chan_wstream(channel) != NULL && chan_wstream(channel)->closed) - || (chan_rstream(channel) != NULL && chan_rstream(channel)->closed)) { - char buf[256]; - snprintf(buf, sizeof(buf), - "ch %" PRIu64 ": stream closed unexpectedly. " - "closing channel", - channel->id); - call_set_error(channel, buf, WARN_LOG_LEVEL); - goto end; - } - size_t count = rbuffer_size(rbuf); DLOG("ch %" PRIu64 ": parsing %u bytes from msgpack Stream: %p", channel->id, count, stream); @@ -571,23 +562,6 @@ static Stream *chan_wstream(Channel *chan) abort(); } -/// Returns the Stream that a Channel reads from. -static Stream *chan_rstream(Channel *chan) -{ - switch (chan->type) { - case kChannelTypeSocket: - return &chan->data.stream; - case kChannelTypeProc: - return chan->data.proc->out; - case kChannelTypeStdio: - return &chan->data.std.in; - case kChannelTypeInternal: - return NULL; - } - abort(); -} - - static bool channel_write(Channel *channel, WBuffer *buffer) { bool success = false; @@ -799,6 +773,12 @@ static void close_cb(Stream *stream, void *data) decref(data); } +static void close_cb2(Stream *stream, void *data) +{ + ILOG("close_cb2"); + close_channel(data); +} + /// @param source description of source function, rplugin name, TCP addr, etc static Channel *register_channel(ChannelType type, uint64_t id, MultiQueue *events, char *source) --- src/nvim/log.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index 3baf0b2ebd..436a8a4079 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -250,7 +250,7 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, static const char *log_levels[] = { [DEBUG_LOG_LEVEL] = "DEBUG", [INFO_LOG_LEVEL] = "INFO ", - [WARNING_LOG_LEVEL] = "WARN ", + [WARN_LOG_LEVEL] = "WARN ", [ERROR_LOG_LEVEL] = "ERROR", }; assert(log_level >= DEBUG_LOG_LEVEL && log_level <= ERROR_LOG_LEVEL); -- cgit From 63c64705058e96368cbc1dcc3fc4f97fc51c73fe Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Sat, 2 Sep 2017 11:35:53 +0200 Subject: log: introduce `context` --- src/nvim/log.c | 40 ++++++++++++++++++++++++++-------------- 1 file changed, 26 insertions(+), 14 deletions(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index 436a8a4079..a8451f7bc4 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -95,8 +95,12 @@ void log_unlock(void) uv_mutex_unlock(&mutex); } -bool do_log(int log_level, const char *func_name, int line_num, bool eol, - const char* fmt, ...) FUNC_ATTR_UNUSED +/// @param context description of a shared context or subsystem +/// @param func_name function name, or NULL +/// @param line_num source line number, or -1 +bool do_log(int log_level, const char *context, const char *func_name, + int line_num, bool eol, const char* fmt, ...) + FUNC_ATTR_UNUSED { if (log_level < MIN_LOG_LEVEL) { return false; @@ -112,8 +116,8 @@ bool do_log(int log_level, const char *func_name, int line_num, bool eol, va_list args; va_start(args, fmt); - ret = v_do_log_to_file(log_file, log_level, func_name, line_num, eol, - fmt, args); + ret = v_do_log_to_file(log_file, log_level, context, func_name, line_num, + eol, fmt, args); va_end(args); if (log_file != stderr && log_file != stdout) { @@ -151,7 +155,7 @@ 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, + do_log_to_file(stderr, ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true, "Cannot LOG() recursively."); return stderr; } @@ -171,7 +175,7 @@ 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, __func__, __LINE__, true, + 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); return stderr; @@ -201,7 +205,7 @@ void log_callstack_to_file(FILE *log_file, const char *const func_name, // 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, func_name, line_num, true, + do_log_to_file(log_file, DEBUG_LOG_LEVEL, NULL, func_name, line_num, true, "trace:"); FILE *fp = popen(cmdbuf, "r"); char linebuf[IOSIZE]; @@ -230,22 +234,23 @@ end: } #endif -static bool do_log_to_file(FILE *log_file, int log_level, +static bool do_log_to_file(FILE *log_file, int log_level, const char *context, const char *func_name, int line_num, bool eol, const char* fmt, ...) { va_list args; va_start(args, fmt); - bool ret = v_do_log_to_file(log_file, log_level, func_name, line_num, eol, - fmt, args); + bool ret = v_do_log_to_file(log_file, log_level, context, func_name, + line_num, eol, fmt, args); va_end(args); return ret; } static bool v_do_log_to_file(FILE *log_file, int log_level, - const char *func_name, int line_num, bool eol, - const char* fmt, va_list args) + const char *context, const char *func_name, + int line_num, bool eol, const char* fmt, + va_list args) { static const char *log_levels[] = { [DEBUG_LOG_LEVEL] = "DEBUG", @@ -268,8 +273,15 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, // print the log message prefixed by the current timestamp and pid int64_t pid = os_get_pid(); - if (fprintf(log_file, "%s %s %" PRId64 "/%s:%d: ", date_time, - log_levels[log_level], pid, func_name, line_num) < 0) { + int rv = (line_num == -1 || func_name == NULL) + ? fprintf(log_file, "%s %s %" PRId64 " %s", date_time, + log_levels[log_level], pid, + (context == NULL ? "?:" : context)) + : fprintf(log_file, "%s %s %" PRId64 " %s%s:%d: ", date_time, + log_levels[log_level], pid, + (context == NULL ? "" : context), + func_name, line_num); + if (rv < 0) { return false; } if (vfprintf(log_file, fmt, args) < 0) { -- cgit From 8716994cf07e9c9dab4af31a0acf47c858a1b789 Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Sat, 2 Sep 2017 17:04:42 +0200 Subject: lint --- src/nvim/log.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'src/nvim/log.c') diff --git a/src/nvim/log.c b/src/nvim/log.c index a8451f7bc4..7bfe5c4089 100644 --- a/src/nvim/log.c +++ b/src/nvim/log.c @@ -99,7 +99,7 @@ void log_unlock(void) /// @param func_name function name, or NULL /// @param line_num source line number, or -1 bool do_log(int log_level, const char *context, const char *func_name, - int line_num, bool eol, const char* fmt, ...) + int line_num, bool eol, const char *fmt, ...) FUNC_ATTR_UNUSED { if (log_level < MIN_LOG_LEVEL) { @@ -249,7 +249,7 @@ static bool do_log_to_file(FILE *log_file, int log_level, const char *context, static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context, const char *func_name, - int line_num, bool eol, const char* fmt, + int line_num, bool eol, const char *fmt, va_list args) { static const char *log_levels[] = { -- cgit