aboutsummaryrefslogtreecommitdiff
path: root/test/functional/core/log_spec.lua
diff options
context:
space:
mode:
authorJustin M. Keyes <justinkz@gmail.com>2022-05-23 21:44:15 -0700
committerJustin M. Keyes <justinkz@gmail.com>2022-06-15 19:23:10 -0700
commit8f065205946844d87f00d6c55517521e3809f821 (patch)
tree7201a15d3b8f8992fc67a3769ffb6ad06657b9d4 /test/functional/core/log_spec.lua
parentfa4b0c3ba5c4aa6dce90cf9d5fb63ea65fd0daee (diff)
downloadrneovim-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.lua55
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)