From fe1af9c2bc020cdb9e1e86e1f16d6060246f957a Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Tue, 30 May 2017 02:03:08 +0200 Subject: 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 --- src/nvim/log.h | 74 ++++++++++++++++++++++++++-------------------------------- 1 file changed, 33 insertions(+), 41 deletions(-) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 32b7276f14..221f0bbaf6 100644 --- a/src/nvim/log.h +++ b/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 - -# 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 +#define LOG(level, ...) do_log((level), __func__, __LINE__, true, \ + __VA_ARGS__) -# 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 +#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 -# 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 +#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 -# 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 +#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 +#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 #ifdef INCLUDE_GENERATED_DECLARATIONS -- cgit From 5fc775e2efd1adf4985d9abcb1d970dcaa944555 Mon Sep 17 00:00:00 2001 From: Yichao Zhou Date: Thu, 13 Apr 2017 22:06:19 +0200 Subject: log.h: LOG_CALLSTACK --- src/nvim/log.h | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 221f0bbaf6..48be7606e7 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -61,6 +61,30 @@ __VA_ARGS__) #endif +#if defined(__linux__) +# include +# define LOG_CALLSTACK(prefix) \ + do { \ + void *trace[100]; \ + int trace_size = backtrace(trace, 100); \ + \ + char exe[1024]; \ + ssize_t elen = readlink("/proc/self/exe", exe, sizeof(exe) - 1); \ + exe[elen] = 0; \ + \ + for (int i = 1; i < trace_size; i++) { \ + char buf[256]; \ + snprintf(buf, sizeof(buf), "addr2line -e %s -f -p %p", exe, trace[i]); \ + FILE *fp = popen(buf, "r"); \ + while (fgets(buf, sizeof(buf) - 1, fp) != NULL) { \ + buf[strlen(buf)-1] = 0; \ + do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, prefix "%s", buf); \ + } \ + fclose(fp); \ + } \ + } while (0) +#endif + #ifdef INCLUDE_GENERATED_DECLARATIONS # include "log.h.generated.h" #endif -- cgit 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.h | 22 +--------------------- 1 file changed, 1 insertion(+), 21 deletions(-) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 48be7606e7..2bd18f5776 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -62,27 +62,7 @@ #endif #if defined(__linux__) -# include -# define LOG_CALLSTACK(prefix) \ - do { \ - void *trace[100]; \ - int trace_size = backtrace(trace, 100); \ - \ - char exe[1024]; \ - ssize_t elen = readlink("/proc/self/exe", exe, sizeof(exe) - 1); \ - exe[elen] = 0; \ - \ - for (int i = 1; i < trace_size; i++) { \ - char buf[256]; \ - snprintf(buf, sizeof(buf), "addr2line -e %s -f -p %p", exe, trace[i]); \ - FILE *fp = popen(buf, "r"); \ - while (fgets(buf, sizeof(buf) - 1, fp) != NULL) { \ - buf[strlen(buf)-1] = 0; \ - do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, prefix "%s", buf); \ - } \ - fclose(fp); \ - } \ - } while (0) +# define LOG_CALLSTACK() log_callstack(__func__, __LINE__) #endif #ifdef INCLUDE_GENERATED_DECLARATIONS -- 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.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 2bd18f5776..743a8d17aa 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -61,7 +61,7 @@ __VA_ARGS__) #endif -#if defined(__linux__) +#ifdef HAVE_EXECINFO_BACKTRACE # define LOG_CALLSTACK() log_callstack(__func__, __LINE__) #endif -- 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.h | 1 + 1 file changed, 1 insertion(+) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 743a8d17aa..5064d9333b 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -63,6 +63,7 @@ #ifdef HAVE_EXECINFO_BACKTRACE # define LOG_CALLSTACK() log_callstack(__func__, __LINE__) +# define LOG_CALLSTACK_TO_FILE(fp) log_callstack_to_file(fp, __func__, __LINE__) #endif #ifdef INCLUDE_GENERATED_DECLARATIONS -- 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.h | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index 5064d9333b..d63bcc366c 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -6,7 +6,7 @@ #define DEBUG_LOG_LEVEL 0 #define INFO_LOG_LEVEL 1 -#define WARNING_LOG_LEVEL 2 +#define WARN_LOG_LEVEL 2 #define ERROR_LOG_LEVEL 3 #define DLOG(...) @@ -43,12 +43,12 @@ __VA_ARGS__) #endif -#if MIN_LOG_LEVEL <= WARNING_LOG_LEVEL +#if MIN_LOG_LEVEL <= WARN_LOG_LEVEL # undef WLOG # undef WLOGN -# define WLOG(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, true, \ +# define WLOG(...) do_log(WARN_LOG_LEVEL, __func__, __LINE__, true, \ __VA_ARGS__) -# define WLOGN(...) do_log(WARNING_LOG_LEVEL, __func__, __LINE__, false, \ +# define WLOGN(...) do_log(WARN_LOG_LEVEL, __func__, __LINE__, false, \ __VA_ARGS__) #endif -- 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.h | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) (limited to 'src/nvim/log.h') diff --git a/src/nvim/log.h b/src/nvim/log.h index d63bcc366c..f378b92039 100644 --- a/src/nvim/log.h +++ b/src/nvim/log.h @@ -22,42 +22,42 @@ # define MIN_LOG_LEVEL INFO_LOG_LEVEL #endif -#define LOG(level, ...) do_log((level), __func__, __LINE__, true, \ +#define LOG(level, ...) do_log((level), NULL, __func__, __LINE__, true, \ __VA_ARGS__) #if MIN_LOG_LEVEL <= DEBUG_LOG_LEVEL # undef DLOG # undef DLOGN -# define DLOG(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, true, \ +# define DLOG(...) do_log(DEBUG_LOG_LEVEL, NULL, __func__, __LINE__, true, \ __VA_ARGS__) -# define DLOGN(...) do_log(DEBUG_LOG_LEVEL, __func__, __LINE__, false, \ +# define DLOGN(...) do_log(DEBUG_LOG_LEVEL, NULL, __func__, __LINE__, false, \ __VA_ARGS__) #endif #if MIN_LOG_LEVEL <= INFO_LOG_LEVEL # undef ILOG # undef ILOGN -# define ILOG(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, true, \ +# define ILOG(...) do_log(INFO_LOG_LEVEL, NULL, __func__, __LINE__, true, \ __VA_ARGS__) -# define ILOGN(...) do_log(INFO_LOG_LEVEL, __func__, __LINE__, false, \ +# define ILOGN(...) do_log(INFO_LOG_LEVEL, NULL, __func__, __LINE__, false, \ __VA_ARGS__) #endif #if MIN_LOG_LEVEL <= WARN_LOG_LEVEL # undef WLOG # undef WLOGN -# define WLOG(...) do_log(WARN_LOG_LEVEL, __func__, __LINE__, true, \ +# define WLOG(...) do_log(WARN_LOG_LEVEL, NULL, __func__, __LINE__, true, \ __VA_ARGS__) -# define WLOGN(...) do_log(WARN_LOG_LEVEL, __func__, __LINE__, false, \ +# define WLOGN(...) do_log(WARN_LOG_LEVEL, NULL, __func__, __LINE__, false, \ __VA_ARGS__) #endif #if MIN_LOG_LEVEL <= ERROR_LOG_LEVEL # undef ELOG # undef ELOGN -# define ELOG(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, true, \ +# define ELOG(...) do_log(ERROR_LOG_LEVEL, NULL, __func__, __LINE__, true, \ __VA_ARGS__) -# define ELOGN(...) do_log(ERROR_LOG_LEVEL, __func__, __LINE__, false, \ +# define ELOGN(...) do_log(ERROR_LOG_LEVEL, NULL, __func__, __LINE__, false, \ __VA_ARGS__) #endif -- cgit