From 8f065205946844d87f00d6c55517521e3809f821 Mon Sep 17 00:00:00 2001
From: "Justin M. Keyes" <justinkz@gmail.com>
Date: Mon, 23 May 2022 21:44:15 -0700
Subject: feat(logging): include test-id in log messages
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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
---
 test/functional/core/log_spec.lua | 55 +++++++++++++++++++++++++++++++++++++++
 1 file changed, 55 insertions(+)
 create mode 100644 test/functional/core/log_spec.lua

(limited to 'test/functional/core/log_spec.lua')

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)
-- 
cgit