Commit Graph

50 Commits

Author SHA1 Message Date
Justin M. Keyes
4d9e2247c9 refactor(log): simplify log_path_init #18898
Problem:
Since 22b52dd462 #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.
2022-06-08 08:47:34 -07:00
bfredl
8c86feb930 fix(log): back even again 2022-06-03 16:26:50 +02:00
bfredl
640c695a7b fix(logging): make logmsg() thread-safe again
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
2022-06-03 11:08:32 +02:00
Justin M. Keyes
f6e19e7334 fix(logging): skip recursion, fix crash #18764
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.
2022-05-30 13:07:33 -07:00
Ivan
78a1e6bc00 feat(defaults): session data in $XDG_STATE_HOME #15583
See: 4f2884e16d

- 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
2022-05-12 07:13:45 -07:00
Lewis Russell
fcd57980f9 chore: add additional compiler flags (#17815)
Added:
  - -Wdouble-promotion
  - -Wmissing-noreturn
  - -Wmissing-format-attribute
  - -Wsuggest-attribute={pure,const,malloc,cold}

Resolves: #343
2022-03-24 12:14:04 +01:00
dundargoc
f4ca3a29dd refactor: reformat with uncrustify #15736
* fix function parameter comments
* remove space after star in function names
2021-09-20 09:35:41 -07:00
Michael Lingelbach
640febaca7 log.c: warn instead of error on failed stdpath('cache') creation 2021-01-16 18:58:11 -08:00
Michael Lingelbach
abbfaf286f logs: make kXDGCacheHome if it doesn't exist (#13758) 2021-01-16 21:14:59 +01:00
Michael Lingelbach
ea8756f85d logging: move to XDG_CACHE_HOME (#13739)
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`.
2021-01-13 23:20:21 +01:00
Jan Edmund Lazo
8ae34ab780 log: use uv_gettimeofday() for Windows
POSIX gettimeofday() is not portable.
2020-12-06 19:26:33 -05:00
Daniel Hahler
22b52dd462 log_init: call log_path_init (#11501)
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.
2019-12-02 22:21:15 +01:00
Jan Edmund Lazo
6508215b5c Remove excess <stdint.h> 2019-09-11 22:27:45 -04:00
Justin M. Keyes
27cd1e07ed doc [ci skip]
- README.md: Removed waffle.io because that service is shutting down.
2019-04-08 03:42:21 +02:00
Justin M. Keyes
dbba685c69 build: include auto/config.h explicitly
Otherwise the symbols defined in config/config.h.in may not be defined,
depending on include-order.
2019-01-20 00:18:39 +01:00
Justin M. Keyes
512e0caae2 Merge #9036 'func_attr_printf' 2018-10-07 19:36:01 +02:00
James McCoy
d59bf058ab log: Assert that we haven't started freeing memory before logging
This is to catch situations like the previous commit, which somehow
avoided detection by any of the CI builds.
2018-09-24 22:56:24 -04:00
MichaHoffmann
8cb04c2230 fixed lint errors 2018-09-24 22:05:01 +02:00
MichaHoffmann
affef0aab8 add func_attr_printf in :
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
2018-09-24 21:28:04 +02:00
Justin M. Keyes
b9bcfa9bc8 log: rename do_log to logmsg 2018-09-19 00:58:25 +02:00
hyatskov
bb33fc4f55 log.c: Fix possible truncation in buffer (#8791) 2018-07-29 01:38:17 +02:00
Justin M. Keyes
27dc42160f log.c: format: padding
- milliseconds: leading zeroes
- PID: whitespace padding
2018-07-25 15:29:57 +02:00
Justin M. Keyes
ef86aad878 log.c: ISO 8601 date/time
After:
    INFO  2018-07-17T22:05:46.175 656 main:560: starting main loop
2018-07-24 19:36:38 +02:00
Justin M. Keyes
3258c6a2f4 log.c: include milliseconds
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.
2018-07-24 19:36:38 +02:00
Justin M. Keyes
4d6a1e5566 log.c: message format
- 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
2018-07-24 19:25:51 +02:00
Justin M. Keyes
ddea519542 rename: os_get_localtime => os_localtime 2018-07-24 19:25:50 +02:00
Justin M. Keyes
8716994cf0 lint 2017-09-05 15:01:07 +02:00
Justin M. Keyes
63c6470505 log: introduce context 2017-09-05 15:01:07 +02:00
Justin M. Keyes
af993da435 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=<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)
2017-08-21 01:04:28 +02:00
James McCoy
17eb20b22e log: Add log_callstack_to_file()
This makes it trivial to log the callstack to, e.g., stderr, which can
simplify debug cycles.
2017-08-09 13:30:34 -04:00
Justin M. Keyes
a7538371fe build: linux does not always have execinfo.h (#7101)
Closes #7099
2017-07-30 23:02:41 +02:00
Justin M. Keyes
eb2473e9ea log: log_callstack() 2017-07-23 17:16:19 +02:00
Justin M. Keyes
d07661b9a3 log: Fall back to CWD-relative .nvimlog
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.
2017-06-07 00:27:26 +02:00
Justin M. Keyes
bb96b8219d log: set $NVIM_LOG_FILE; fallback to $XDG_DATA_HOME/nvim/log 2017-06-07 00:26:56 +02:00
Justin M. Keyes
fe1af9c2bc 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
2017-06-07 00:26:21 +02:00
Justin M. Keyes
f83d733318 log: log_uv_handles 2017-06-07 00:26:19 +02:00
ZyX
c2f3e361c5 *: Add comment to all C files 2017-04-19 19:11:50 +03:00
Justin M. Keyes
7e6a8310b7 log.c: align/adjust layout
New:
  2016/09/27 18:00:49 INFO  28117/tui_flush:597: ...

Old:
  2016/09/27 18:00:49 [info @ tui_flush:597] 28117 - ...
2016-09-28 03:29:55 +02:00
Justin M. Keyes
cc8a2e7aad log: Rename to $NVIM_LOG_FILE 2016-06-05 04:14:54 -04:00
ZyX
d0bd023881 log: Move log to $NVIM_LOG_FILE_PATH, falling back to the old location
Closes #3561
2016-05-31 16:36:49 +03:00
Seth Jackson
33321f2c85 config: Remove HAVE_UNISTD_H.
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.
2016-01-18 13:48:47 -05:00
Rui Abreu Ferreira
0ab4f2f18f Update USR_LOG_FILE definition. 2015-12-07 19:26:26 -05:00
Thiago de Arruda
2a0ff9f5cf log: Make logging thread-safe 2015-09-06 09:18:52 -03:00
Justin M. Keyes
7280e8c365 remove references to <sys/time.h>
Since gettimeofday() was replaced by os_time in
fb5a786bdb we do not need sys/time.h.
2015-08-24 00:27:30 -04:00
Rui Abreu Ferreira
e1f83d304d Add header guards for sys/time.h and unistd.h in log.c 2015-05-21 02:09:49 -04:00
bobtwinkles
03d47965c0 refactor: split some more functions from misc1.c
This commit pulls the some environment-variable handling functions out of
misc1.c and in to os/env.c. Previously submited as #1231, this is the start of
a patch series that does that work based on a more up-to-date master branch.

Major tasks accomplished:
  - move functions and fix includes
  - fix clint/clang analysis warnings
  - correct documentation comments
2015-03-24 16:13:00 -04:00
Thiago de Arruda
64844b7312 msgpack-rpc: Improve logging of msgpack-rpc messages
- Expose more logging control from the log.c module(get log stream and omit
  newlines)
- Remove logging from the generated functions in msgpack-gen.lua
- Refactor channel.c/helpers.c to log every msgpack-rpc payload using
  msgpack_object_print(a helper function from msgpack.h)
- Remove the api_stringify function, it was only useful for logging msgpack-rpc
  which is now handled by msgpack_object_print.
2014-10-23 21:46:03 -03:00
ZyX
70929f7e16 Add automatic generation of headers
- The 'stripdecls.py' script replaces declarations in all headers by includes to
  generated headers.
  `ag '#\s*if(?!ndef NEOVIM_).*((?!#\s*endif).*\n)*#ifdef INCLUDE_GENERATED'`
  was used for this.
- Add and integrate gendeclarations.lua into the build system to generate the
  required includes.
- Add -Wno-unused-function
- Made a bunch of old-style definitions ANSI

This adds a requirement: all type and structure definitions must be present
before INCLUDE_GENERATED_DECLARATIONS-protected include.

Warning: mch_expandpath (path.h.generated.h) was moved manually. So far it is
the only exception.
2014-06-02 11:04:17 -03:00
Eliseo Martínez
409cc138f2 Introduce nvim namespace: Fix project-local includes.
Prepend 'nvim/' in all project-local (non-system) includes.
2014-05-15 20:46:01 +02:00
Eliseo Martínez
da51dc9cf2 Introduce nvim namespace: Move files.
Move files from src/ to src/nvim/.
- src/nvim/ becomes the new root dir for nvim executable sources.
- src/libnvim/ is planned to become root dir of the neovim library.
2014-05-15 20:46:01 +02:00