diff options
author | Justin M. Keyes <justinkz@gmail.com> | 2022-05-23 21:44:15 -0700 |
---|---|---|
committer | Justin M. Keyes <justinkz@gmail.com> | 2022-06-15 19:23:10 -0700 |
commit | 8f065205946844d87f00d6c55517521e3809f821 (patch) | |
tree | 7201a15d3b8f8992fc67a3769ffb6ad06657b9d4 /test/functional/core/log_spec.lua | |
parent | fa4b0c3ba5c4aa6dce90cf9d5fb63ea65fd0daee (diff) | |
download | rneovim-8f065205946844d87f00d6c55517521e3809f821.tar.gz rneovim-8f065205946844d87f00d6c55517521e3809f821.tar.bz2 rneovim-8f065205946844d87f00d6c55517521e3809f821.zip |
feat(logging): include test-id in log messages
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
Diffstat (limited to 'test/functional/core/log_spec.lua')
-rw-r--r-- | test/functional/core/log_spec.lua | 55 |
1 files changed, 55 insertions, 0 deletions
diff --git a/test/functional/core/log_spec.lua b/test/functional/core/log_spec.lua new file mode 100644 index 0000000000..8553197305 --- /dev/null +++ b/test/functional/core/log_spec.lua @@ -0,0 +1,55 @@ +local helpers = require('test.functional.helpers')(after_each) +local assert_log = helpers.assert_log +local clear = helpers.clear +local eq = helpers.eq +local exec_lua = helpers.exec_lua +local request = helpers.request +local retry = helpers.retry +local expect_exit = helpers.expect_exit + +describe('log', function() + local test_log_file = 'Xtest_logging' + + after_each(function() + expect_exit('qa!') + os.remove(test_log_file) + end) + + it('skipped before log_init', function() + -- This test is for _visibility_: adjust as needed, after checking for regression. + -- + -- During startup some components may try to log before logging is setup. + -- That should be uncommon (ideally never)--and if there are MANY such + -- calls, that needs investigation. + clear() + eq(0, request('nvim__stats').log_skip) + clear{env={CDPATH='~doesnotexist'}} + assert(request('nvim__stats').log_skip <= 13) + end) + + it('messages are formatted with name or test id', function() + -- Examples: + -- ERR 2022-05-29T12:30:03.800 T2 log_init:110: test log message + -- ERR 2022-05-29T12:30:03.814 T2/child log_init:110: test log message + + clear({env={ + NVIM_LOG_FILE=test_log_file, + -- TODO: Can remove this after nvim_log #7062 is merged. + __NVIM_TEST_LOG='1' + }}) + + retry(nil, nil, function() + assert_log('T%d+\\.%d+\\.\\d +log_init:%d+: test log message', test_log_file, 100) + end) + + exec_lua([[ + local j1 = vim.fn.jobstart({ vim.v.progpath, '-es', '-V1', '+foochild', '+qa!' }, vim.empty_dict()) + vim.fn.jobwait({ j1 }, 10000) + ]]) + + -- Child Nvim spawned by jobstart() appends "/child" to parent name. + retry(nil, nil, function() + assert_log('T%d+/child +log_init:%d+: test log message', test_log_file, 100) + end) + end) +end) |