aboutsummaryrefslogtreecommitdiff
path: root/src/nvim/log.c
Commit message (Collapse)AuthorAge
* build: allow IWYU to fix includes for all .c filesdundargoc2022-11-15
| | | | | | | | | | Allow Include What You Use to remove unnecessary includes and only include what is necessary. This helps with reducing compilation times and makes it easier to visualise which dependencies are actually required. Work on https://github.com/neovim/neovim/issues/549, but doesn't close it since this only works fully for .c files and not headers.
* refactor: replace char_u with char 4 (#19987)dundargoc2022-08-30
| | | | | | | * refactor: replace char_u with char Work on https://github.com/neovim/neovim/issues/459
* refactor: replace char_u with charDundar Göc2022-08-29
| | | | Work on https://github.com/neovim/neovim/issues/459
* refactor: fix clang and PVS warnings (#19532)zeertzjq2022-07-28
|
* fix(logging): try harder to resolve Nvim "name" #19016Justin M. Keyes2022-06-18
| | | | | | | | | | | Problem: If startup finishes (starting=false) before the logger ever happens to see a v:servername, we're stuck with the "?.<PID>" fallback name forever. Solution: Drop the `starting` condition. Discard the "?.<PID>" fallback after using it for the current log message. So logging will always check v:servername next time.
* feat(server): instance "name", store pipes in stdpath(state)Justin M. Keyes2022-06-15
| | | | | | | | | | | | | | | | | | Problem: - Unix sockets are created in random /tmp dirs. - /tmp is messy, unclear when OSes actually clear it. - The generated paths are very ugly. This adds friction to reasoning about which paths belong to which Nvim instances. - No way to provide a human-friendly way to identify Nvim instances in logs or server addresses. Solution: - Store unix sockets in stdpath('state') - Allow --listen "name" and serverstart("name") to given a name (which is appended to a generated path). TODO: - is stdpath(state) the right place?
* feat(logging): include test-id in log messagesJustin M. Keyes2022-06-15
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | Problem: 1. Log messages (especially in CI) are hard to correlate with tests. 2. Since b353a5c05f02 #11886, dumplog() prints the logs next to test failures. This is noisy and gets in the way of the test results. Solution: 1. Associate an incrementing id with each test and include it in log messages. - FUTURE: add v:name so Nvim instances can be formally "named"? 2. Mention "child" in log messages if the current Nvim is a child (based on the presence of $NVIM). BEFORE: DBG … 12345 UI: event DBG … 12345 log_server_msg:722: RPC ->ch 1: … DBG … 12345 UI: flush DBG … 12345 inbuf_poll:444: blocking... events_enabled=1 events_pending=0 DBG … 23454 UI: stop INF … 23454 os_exit:594: Nvim exit: 0 AFTER: DBG … T57 UI: event DBG … T57 log_server_msg:722: RPC ->ch 1: … DBG … T57 UI: flush DBG … T57 inbuf_poll:444: blocking... events_enabled=1 events_pending=0 DBG … T57/child UI: stop INF … T57/child os_exit:594: Nvim exit: 0
* refactor(log): use msg_schedule_semsg #18950Justin M. Keyes2022-06-15
|
* refactor(log): simplify log_path_init #18898Justin M. Keyes2022-06-08
| | | | | | | | | Problem: Since 22b52dd462e5 #11501, log_path_init is called in log_init, so it is now called at a deterministic time. So the "just in time" complexity of log_path_init is no longer needed. Solution: Remove logic intended to try to "heal" partial initialization.
* fix(log): back even againbfredl2022-06-03
|
* fix(logging): make logmsg() thread-safe againbfredl2022-06-03
| | | | | | | | | problem: data race when `recursive` is read outside of mutex by thread A while thread B has taken the mutex and modifies it. solution: use a recursive lock. ref #18764
* fix(logging): skip recursion, fix crash #18764Justin M. Keyes2022-05-30
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | Problem: 1. The main log routine does not protect itself against recursion. log_lock() doesn't guard against recursion, it would deadlock... 2. 22b52dd462e5 (#11501) regressed 6f27f5ef91b3 (#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.
* feat(defaults): session data in $XDG_STATE_HOME #15583Ivan2022-05-12
| | | | | | | | | | | | See: https://gitlab.freedesktop.org/xdg/xdg-specs/-/commit/4f2884e16db35f2962d9b64312917c81be5cb54b - Move session persistent data to $XDG_STATE_HOME Change 'directory', 'backupdir', 'undodir', 'viewdir' and 'shadafile' default location to $XDG_STATE_HOME/nvim. - Move logs to $XDG_STATE_HOME, too. - Add stdpath('log') support. Fixes: #14805
* chore: add additional compiler flags (#17815)Lewis Russell2022-03-24
| | | | | | | | | Added: - -Wdouble-promotion - -Wmissing-noreturn - -Wmissing-format-attribute - -Wsuggest-attribute={pure,const,malloc,cold} Resolves: #343
* refactor: reformat with uncrustify #15736dundargoc2021-09-20
| | | | * fix function parameter comments * remove space after star in function names
* log.c: warn instead of error on failed stdpath('cache') creationMichael Lingelbach2021-01-16
|
* logs: make kXDGCacheHome if it doesn't exist (#13758)Michael Lingelbach2021-01-16
|
* logging: move to XDG_CACHE_HOME (#13739)Michael Lingelbach2021-01-13
| | | | | while there is some controversy, stdpath('cache') looks like a better fit for logs than stdpath('data'): you can remove logs without preventing nvim to work which fits the XDG_CACHE_HOME definition of `user specific non-essential data files`.
* log: use uv_gettimeofday() for WindowsJan Edmund Lazo2020-12-06
| | | | POSIX gettimeofday() is not portable.
* log_init: call log_path_init (#11501)Daniel Hahler2019-12-02
| | | | | | | | This has to be done after `init_homedir` for XDG default and `set_init_1` for lookup from env, which could be done earlier likely (to help with https://github.com/neovim/neovim/issues/10937), but this keeps it in sync with Vim. Fixes https://github.com/neovim/neovim/issues/11499.
* Remove excess <stdint.h>Jan Edmund Lazo2019-09-11
|
* doc [ci skip]Justin M. Keyes2019-04-08
| | | | - README.md: Removed waffle.io because that service is shutting down.
* build: include auto/config.h explicitlyJustin M. Keyes2019-01-20
| | | | | Otherwise the symbols defined in config/config.h.in may not be defined, depending on include-order.
* Merge #9036 'func_attr_printf'Justin M. Keyes2018-10-07
|\
| * fixed lint errorsMichaHoffmann2018-09-24
| |
| * add func_attr_printf in :MichaHoffmann2018-09-24
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | log.c message.c strings.c fixed some printf warnings in: src/nvim/undo.c src/nvim/eval.c src/nvim/eval/encode.c src/nvim/eval/typval.c src/nvim/ex_getln.c src/nvim/fileio.c src/nvim/lua/executor.c src/nvim/main.c src/nvim/regexp_nfa.c src/nvim/shada.c src/nvim/spellfile.c src/nvim/tui/terminfo.c src/nvim/garray.h
* | log: Assert that we haven't started freeing memory before loggingJames McCoy2018-09-24
|/ | | | | This is to catch situations like the previous commit, which somehow avoided detection by any of the CI builds.
* log: rename do_log to logmsgJustin M. Keyes2018-09-19
|
* log.c: Fix possible truncation in buffer (#8791)hyatskov2018-07-29
|
* log.c: format: paddingJustin M. Keyes2018-07-25
| | | | | - milliseconds: leading zeroes - PID: whitespace padding
* log.c: ISO 8601 date/timeJustin M. Keyes2018-07-24
| | | | | After: INFO 2018-07-17T22:05:46.175 656 main:560: starting main loop
* log.c: include millisecondsJustin M. Keyes2018-07-24
| | | | | | | | | | | | | closes #8727 Before: INFO 180711.233956 11124 main:560: starting main loop After: INFO 180711.233956.807 11124 main:560: starting main loop Note: - Can't use uv_hrtime() nor uv_now(), they are not "since the epoch". Also, log.c can't assume a loop exists.
* log.c: message formatJustin M. Keyes2018-07-24
| | | | | | | | | | | | - Log-level name (INFO/ERROR/…) should be in the first column, so that filtering by log-level is maximally trivial. - Use 2-digit year. 4-digit year is useless, logs don't survive for decades without context. Before: 2018/07/05 17:49:41 INFO 27596 on_process_exit:393: foo After: INFO 180705.174941 27596 on_process_exit:393: foo
* rename: os_get_localtime => os_localtimeJustin M. Keyes2018-07-24
|
* lintJustin M. Keyes2017-09-05
|
* log: introduce `context`Justin M. Keyes2017-09-05
|
* rpc: close channel if stream was closedJustin M. Keyes2017-08-21
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | 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=<optimized out>, 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 <justinkz@gmail.com> 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)
* log: Add log_callstack_to_file()James McCoy2017-08-09
| | | | | This makes it trivial to log the callstack to, e.g., stderr, which can simplify debug cycles.
* build: linux does not always have execinfo.h (#7101)Justin M. Keyes2017-07-30
| | | Closes #7099
* log: log_callstack()Justin M. Keyes2017-07-23
|
* log: Fall back to CWD-relative .nvimlogJustin M. Keyes2017-06-07
| | | | | | If if the resolved $NVIM_LOG_FILE *and* stdpath("data")/log cannot be created (e.g. because the XDG data directory does not exist), fall back to .nvimlog in the current direcrtory.
* log: set $NVIM_LOG_FILE; fallback to $XDG_DATA_HOME/nvim/logJustin M. Keyes2017-06-07
|
* log: Always enable; remove DISABLE_LOGJustin M. Keyes2017-06-07
| | | | | | - 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
* log: log_uv_handlesJustin M. Keyes2017-06-07
|
* *: Add comment to all C filesZyX2017-04-19
|
* log.c: align/adjust layoutJustin M. Keyes2016-09-28
| | | | | | | | New: 2016/09/27 18:00:49 INFO 28117/tui_flush:597: ... Old: 2016/09/27 18:00:49 [info @ tui_flush:597] 28117 - ...
* log: Rename to $NVIM_LOG_FILEJustin M. Keyes2016-06-05
|
* log: Move log to $NVIM_LOG_FILE_PATH, falling back to the old locationZyX2016-05-31
| | | | Closes #3561
* config: Remove HAVE_UNISTD_H.Seth Jackson2016-01-18
| | | | | | | | | Unix systems must have this header but Windows does not have it at all. Since src/nvim/os/unix_defs.h includes <unistd.h> without the guard in order to avoid including this in the numerous places we would need <unistd.h> on Unix we just include src/nvim/os/os.h which will pull in <unistd.h> for us.
* Update USR_LOG_FILE definition.Rui Abreu Ferreira2015-12-07
|
generated by cgit (git 2.34.1) at 2025-08-03 10:15:09 +0000