[RDY] Always enable logging #6827

justinmk · 2017-05-30T13:10:04Z

Goals of this PR:

change the default log location to ~/.local/share/nvim/log
set NVIM_LOG_FILE to the default path if it is undefined
Establish ERROR log level as critical, rare errors that must be logged. There are cases where we have no visibility in hangs/crashes because logging is disabled.
- With this established, log file for end-users should be small or non-existent, unless there was a severe problem.
Always enable logging, even for "Release" builds. If logging is not noisy then this doesn't affect end-users.
remove DISABLE_LOG
Travis CI: dump the contents of the log file after each run
documentation

Future PR:

nvim_log(level, message) API function
update API clients (python, etc.) to use nvim_log() for critical messages
stdpath('log') ?
log Vim errors that happen during shutdown [RDY] Always enable logging #6827 (comment)

justinmk · 2017-05-30T13:14:22Z

src/nvim/event/loop.c

+      // Some libuv resource was not correctly deref'd. Log and bail.
+      log_uv_handles(&loop->uv);
+      break;
+    }


If loop_close takes longer than 2 seconds it is most likely an infinite loop. So, log the state and exit the loop.

justinmk · 2017-05-30T13:17:30Z

src/nvim/msgpack_rpc/channel.c

@@ -370,7 +370,7 @@ static void receive_msgpack(Stream *stream, RBuffer *rbuf, size_t c,
    char buf[256];
    snprintf(buf, sizeof(buf), "ch %" PRIu64 " was closed by the client",
             channel->id);
-    call_set_error(channel, buf);
+    call_set_error(channel, buf, WARNING_LOG_LEVEL);


This is usually not a failure mode, but a normal situation. So don't log it at ERROR level.

oni-link · 2017-05-30T13:24:19Z

src/nvim/garray.h

@@ -37,7 +37,7 @@ typedef struct growarray {
 static inline void *ga_append_via_ptr(garray_T *gap, size_t item_size)
 {
  if ((int)item_size != gap->ga_itemsize) {
-    ELOG("wrong item size in garray(%d), should be %d", item_size);
+    WLOG("wrong item size in garray(%d), should be %d", item_size);


Are we missing a size argument here?

Looks like it :)

blueyed · 2017-06-01T19:59:05Z

Nice!
btw: would it be possible to also log Vim errors, especially when they happen on shutdown/quitting?
(I've just seen some when quitting Neovim slightly pop up in red, but then it is gone already)

blueyed · 2017-06-01T20:01:01Z

.travis.yml

@@ -21,8 +21,6 @@ env:
    - INSTALL_PREFIX="$HOME/nvim-install"
    # Log directory for Clang sanitizers and Valgrind.
    - LOG_DIR="$BUILD_DIR/log"
-    # Nvim log file.
-    - NVIM_LOG_FILE="$BUILD_DIR/.nvimlog"


Seems to be cleaner to keep it here, no?
Is $BUILD_DIR already setup here (defined above)? (but it seems to work for $LOG_DIR?!)

@blueyed That's part of the temporary commits, I am puzzled about why travis is failing.

oni-link · 2017-06-01T20:55:47Z

src/nvim/os_unix.c

@@ -141,7 +141,8 @@ void mch_exit(int r) FUNC_ATTR_NORETURN
  ui_flush();
  ml_close_all(true);           // remove all memfiles

-  event_teardown();
+  // Exit with error if main_loop did not teardown gracefully.
+  r = event_teardown() ? r : (r || 1);


Why use (r||1) here, it is always 1?

@oni-link You're right, that needs to be a ternary. The intention is to preserve the value of r > 0.

oni-link · 2017-06-02T19:34:22Z

src/nvim/log.c

+      || os_isdir((char_u *)log_file_path)
+      || !log_try_create(log_file_path)) {
+    // Invalid $NVIM_LOG_FILE or failed to expand; fall back to default.
+    memset(log_file_path, 0, size);


This could be removed. The following xstrlcpy() will overwrite this buffer and terminate it with NUL.

oni-link · 2017-06-02T19:35:53Z

src/nvim/log.c

+    xfree(defaultpath);
+    // Fall back to .nvimlog
+    if (len >= size || !log_try_create(log_file_path)) {
+      len = xstrlcpy(log_file_path, ".nvimlog", sizeof(".nvimlog"));


sizeof(".nvimlog") is not the size that is expected here, it should be the size of the destination buffer.

oni-link · 2017-06-02T19:37:11Z

src/nvim/log.c

+    }
+    // Fall back to stderr
+    if (len >= size || !log_try_create(log_file_path)) {
+      memset(log_file_path, 0, size);


log_file_path[0]=NUL; should be enough to mark the buffer as empty.

Avoids a hang, and also helps diagnose issues like: neovim#6594 (comment)

- 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

- Do not delete it: may need to inspect it after tests finished. - Avoids writing to stderr in cases where the test-local $XDG_DATA_HOME was not created yet.

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.

- [ ] `nvim_log(level, message)` API function - [ ] update API clients (python, etc.) to use `nvim_log()` for critical messages - [ ] `stdpath('log')` ? - [ ] log Vim errors that happen during shutdown neovim#6827 (comment)

jdebp · 2017-06-08T14:10:40Z

Development-tips on the wiki needs to be brought up-to-date.

The main purpose of this build-type was to avoid unwanted ~/.nvimlog files (which could get really big, and also affects performance) for non-devs. But that is no longer necessary since the log system now avoids non-critical logging by default (neovim#6827). This essentially reverts 87e5a41

The main purpose of this build-type was to avoid unwanted ~/.nvimlog files (which could get really big, and also affects performance) for non-devs. But that is no longer necessary since the log system now avoids non-critical logging by default (#6827). This essentially reverts 87e5a41

- [ ] `nvim_log(level, message)` API function - [ ] update API clients (python, etc.) to use `nvim_log()` for critical messages - [ ] `stdpath('log')` ? - [ ] log Vim errors that happen during shutdown neovim#6827 (comment)

FEATURES: 0e873a3 Lua(Jit) built-in neovim#4411 5b32bce Windows: `:terminal` neovim#7007 7b0ceb3 UI/API: externalize cmdline neovim#7173 b67f58b UI/API: externalize wildmenu neovim#7454 b23aa1c UI: 'winhighlight' neovim#6597 17531ed UI: command-line coloring (`:help input()-highlight`) neovim#6364 244a1f9 API: execute lua directly from the remote api neovim#6704 45626de API: `get_keymap()` neovim#6236 db99982 API: `nvim_get_hl_by_name()`, `nvim_get_hl_by_id()` neovim#7082 dc68538 menu_get() function neovim#6322 9db42d4 :cquit : take an error code argument neovim#7336 9cc185d job-control: serverstart(): support ipv6 neovim#6680 1b7a9bf job-control: sockopen() neovim#6594 6efe84a clipboard: fallback to tmux clipboard neovim#6894 6016ac2 clipboard: customize clipboard with `g:clipboard` neovim#6030 3a86dd5 ruby: override ruby host via `g:ruby_host_prog` neovim#6841 16cce1a debug: $NVIM_LOG_FILE neovim#6827 0cba3da `:checkhealth` built-in, validates $VIMRUNTIME neovim#7399 FIXES: 105d680 TUI: more terminals, improve scroll/resize neovim#6816 cb912a3 :terminal : handle F1-F12, other keys neovim#7241 619838f inccommand: improve performance neovim#6949 04b3c32 inccommand: Fix matches for zero-width neovim#7487 60b1e8a inccommand: multiline, other fixes neovim#7315 f1f7f3b inccommand: Ignore leading modifiers in the command neovim#6967 1551f71 inccommand: fix 'gdefault' lockup neovim#7262 6338199 API: bufhl: support creating new groups neovim#7414 541dde3 API: allow K_EVENT during operator-pending 8c732f7 terminal: adjust for 'number' neovim#7440 5bec946 UI: preserve wildmenu during jobs/events neovim#7110 c349083 UI: disable 'lazyredraw' during ui_refresh. neovim#6259 51808a2 send FocusGained/FocusLost event instead of pseudokey neovim#7221 133f8bc shada: preserve unnamed register on restart neovim#4700 1b70a1d shada: avoid assertion on corrupt shada file neovim#6958 9f534f3 mksession: Restore tab-local working directory neovim#6859 de1084f fix buf_write() crash neovim#7140 7f76986 syntax: register 'Normal' highlight group neovim#6973 6e7a8c3 RPC: close channel if stream was closed neovim#7081 85f3084 clipboard: disallow recursion; show hint only once neovim#7203 8d1ccb6 clipboard: performance, avoid weird edge-cases neovim#7193 01487d4 'titleold' neovim#7358 01e53a5 Windows: better path-handling, separator (slash) hygiene neovim#7349 0f2873c Windows: multibyte startup arguments neovim#7060 CHANGES: 9ff0cc7 :terminal : start in normal-mode neovim#6808 032b088 lower priority of 'cursorcolumn', 'colorcolumn' neovim#7364 2a3bcd1 RPC: Don't delay notifications when request is pending neovim#6544 023f67c :terminal : Do not change 'number', 'relativenumber' neovim#6796 1ef2d76 socket.c: Disable Nagle's algorithm on TCP sockets neovim#6915 6720fe2 help: `K` tries Vim help instead of manpage neovim#3104 7068370 help, man.vim: change "outline" map to `gO` neovim#7405

justinmk force-pushed the log2 branch from b6f4a66 to 84b7d3a Compare May 30, 2017 13:12

justinmk commented May 30, 2017

View reviewed changes

justinmk force-pushed the log2 branch from 84b7d3a to 61339f3 Compare May 30, 2017 13:19

oni-link reviewed May 30, 2017

View reviewed changes

justinmk force-pushed the log2 branch 3 times, most recently from a5bc0ee to 205c680 Compare May 31, 2017 16:18

blueyed reviewed Jun 1, 2017

View reviewed changes

oni-link reviewed Jun 1, 2017

View reviewed changes

oni-link reviewed Jun 2, 2017

View reviewed changes

justinmk force-pushed the log2 branch 5 times, most recently from d6aa388 to 6617c97 Compare June 6, 2017 02:03

justinmk changed the title ~~Always enable logging~~ [RDY] Always enable logging Jun 6, 2017

justinmk force-pushed the log2 branch 3 times, most recently from 020bbf3 to ab6d0e1 Compare June 6, 2017 15:26

justinmk added 7 commits June 7, 2017 00:26

log: log_uv_handles

f83d733

loop_close: Avoid infinite loop, and log it.

698ec9e

Avoids a hang, and also helps diagnose issues like: neovim#6594 (comment)

log: Always enable; remove DISABLE_LOG

fe1af9c

- 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

ci: Dump $NVIM_LOG_FILE contents

eb6dd3e

ga_append_via_ptr: fix log arguments

05cdbbc

log: set $NVIM_LOG_FILE; fallback to $XDG_DATA_HOME/nvim/log

bb96b82

test: Set $NVIM_LOG_FILE to test-local path

a49c92f

- Do not delete it: may need to inspect it after tests finished. - Avoids writing to stderr in cases where the test-local $XDG_DATA_HOME was not created yet.

justinmk added 3 commits June 7, 2017 00:27

log: Fall back to CWD-relative .nvimlog

d07661b

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.

test: iswin(): detect without nvim session

b4b09af

doc: *standard-path*, *$NVIM_LOG_FILE*

bc025ab

justinmk force-pushed the log2 branch from ab6d0e1 to bc025ab Compare June 6, 2017 22:40

justinmk merged commit 16cce1a into neovim:master Jun 7, 2017

justinmk deleted the log2 branch June 7, 2017 21:19

justinmk mentioned this pull request Jun 7, 2017

log: log_callstack() #6516

Merged

This was referenced Jun 13, 2017

[RDY] fix SIGTERM/SIGHUP for jobs #6823

Merged

process_teardown() hang #6891

Closed

justinmk mentioned this pull request Jun 25, 2017

Move formula into Homebrew/homebrew neovim/homebrew-neovim#115

Closed

justinmk mentioned this pull request Jun 26, 2017

[RDY] cmake: Remove custom "Dev" build-type. #6932

Merged

justinmk mentioned this pull request Jul 23, 2017

logging: nvim_log(), other improvements #7062

Open

6 tasks

justinmk mentioned this pull request Nov 8, 2017

NVIM v0.2.1 #7505

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Uh oh!

[RDY] Always enable logging #6827

[RDY] Always enable logging #6827

Uh oh!

justinmk commented May 30, 2017 •

edited

Loading

Uh oh!

justinmk May 30, 2017

Uh oh!

justinmk May 30, 2017

Uh oh!

oni-link May 30, 2017

Uh oh!

justinmk May 30, 2017

Uh oh!

blueyed commented Jun 1, 2017

Uh oh!

blueyed Jun 1, 2017 •

edited

Loading

Uh oh!

justinmk Jun 1, 2017

Uh oh!

oni-link Jun 1, 2017

Uh oh!

justinmk Jun 1, 2017

Uh oh!

oni-link Jun 2, 2017

Uh oh!

oni-link Jun 2, 2017

Uh oh!

oni-link Jun 2, 2017

Uh oh!

jdebp commented Jun 8, 2017

Uh oh!

Uh oh!

Uh oh!

[RDY] Always enable logging #6827

[RDY] Always enable logging #6827

Uh oh!

Conversation

justinmk commented May 30, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

blueyed commented Jun 1, 2017

Uh oh!

blueyed Jun 1, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jdebp commented Jun 8, 2017

Uh oh!

Uh oh!

justinmk commented May 30, 2017 •

edited

Loading

blueyed Jun 1, 2017 •

edited

Loading