feat(log): use "ui" as default name for TUI client #30345

The default "session name" for the builtin TUI is "ui".

before:

    INF 2024-09-10T14:57:35.385 hello.sock os_exit:692: Nvim exit: 1
    INF 2024-09-10T14:57:35.388 ?.4543     os_exit:692: Nvim exit: 1

after:

    INF 2024-09-10T14:59:19.919 hello.sock os_exit:692: Nvim exit: 1
    INF 2024-09-10T14:59:19.922 ui.5684    os_exit:692: Nvim exit: 1

runtime/doc/news.txt

@@ -189,7 +189,8 @@ TREESITTER
 
 TUI
 
-• TODO
+• |log| messages written by the builtin UI client (TUI, |--remote-ui|) are
+  now prefixed with "ui" instead of "?".
 
 UI
 

src/nvim/log.c

@@ -29,6 +29,7 @@
 #include "nvim/os/stdpaths_defs.h"
 #include "nvim/os/time.h"
 #include "nvim/path.h"
+#include "nvim/ui_client.h"
 
 /// Cached location of the expanded log file path decided by log_path_init().
 static char log_file_path[MAXPATHL + 1] = { 0 };
@@ -322,20 +323,28 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
     millis = (int)curtime.tv_usec / 1000;
   }
 
+  bool ui = !!ui_client_channel_id;  // Running as a UI client (--remote-ui).
+
+  // Regenerate the name when:
+  // - UI client (to ensure "ui" is in the name)
+  // - not set yet
+  // - no v:servername yet
+  bool regen = ui || name[0] == NUL || name[0] == '?';
+
   // Get a name for this Nvim instance.
   // TODO(justinmk): expose this as v:name ?
-  if (name[0] == NUL) {
-    // Parent servername.
+  if (regen) {
+    // Parent servername ($NVIM).
     const char *parent = path_tail(os_getenv(ENV_NVIM));
     // Servername. Empty until starting=false.
     const char *serv = path_tail(get_vim_var_str(VV_SEND_SERVER));
     if (parent[0] != NUL) {
-      snprintf(name, sizeof(name), "%s/c", parent);  // "/c" indicates child.
+      snprintf(name, sizeof(name), ui ? "ui/c/%s" : "c/%s", parent);  // "c/" = child of $NVIM.
     } else if (serv[0] != NUL) {
-      snprintf(name, sizeof(name), "%s", serv);
+      snprintf(name, sizeof(name), ui ? "ui/%s" : "%s", serv);
     } else {
       int64_t pid = os_get_pid();
-      snprintf(name, sizeof(name), "?.%-5" PRId64, pid);
+      snprintf(name, sizeof(name), "%s.%-5" PRId64, ui ? "ui" : "?", pid);
     }
   }
 
@@ -348,10 +357,6 @@ static bool v_do_log_to_file(FILE *log_file, int log_level, const char *context,
                      log_levels[log_level], date_time, millis, name,
                      (context == NULL ? "" : context),
                      func_name, line_num);
-  if (name[0] == '?') {
-    // No v:servername yet. Clear `name` so that the next log can try again.
-    name[0] = NUL;
-  }
 
   if (rv < 0) {
     return false;

src/nvim/msgpack_rpc/server.c

@@ -53,7 +53,7 @@ bool server_init(const char *listen_addr)
 
   int rv = server_start(listen_addr);
 
-  // TODO(justinmk): this is for logging_spec. Can remove this after nvim_log #7062 is merged.
+  // TODO(justinmk): this is for log_spec. Can remove this after nvim_log #7062 is merged.
   if (os_env_exists("__NVIM_TEST_LOG")) {
     ELOG("test log message");
   }

src/nvim/os/input.c

@@ -100,7 +100,7 @@ static void reset_cursorhold_wait(int tb_change_cnt)
 ///
 /// Originally based on the Vim `mch_inchar` function.
 ///
-/// @param buf Buffer to store read input.
+/// @param buf Buffer to store consumed input.
 /// @param maxlen Maximum bytes to read into `buf`, or 0 to skip reading.
 /// @param ms Timeout in milliseconds. -1 for indefinite wait, 0 for no wait.
 /// @param tb_change_cnt Used to detect when typeahead changes.
@@ -493,7 +493,7 @@ static TriState inbuf_poll(int ms, MultiQueue *events)
     blocking = true;
     multiqueue_process_events(ch_before_blocking_events);
   }
-  DLOG("blocking... events=%d pending=%d", !!events, pending_events(events));
+  DLOG("blocking... events=%s", !!events ? "true" : "false");
   LOOP_PROCESS_EVENTS_UNTIL(&main_loop, NULL, ms, os_input_ready(events) || input_eof);
   blocking = false;
 

src/nvim/ui_client.c

@@ -22,6 +22,7 @@
 #include "nvim/memory_defs.h"
 #include "nvim/msgpack_rpc/channel.h"
 #include "nvim/msgpack_rpc/channel_defs.h"
+#include "nvim/os/os.h"
 #include "nvim/os/os_defs.h"
 #include "nvim/tui/tui.h"
 #include "nvim/tui/tui_defs.h"
@@ -126,6 +127,11 @@ void ui_client_run(bool remote_ui)
 
   ui_client_attach(width, height, term, rgb);
 
+  // TODO(justinmk): this is for log_spec. Can remove this after nvim_log #7062 is merged.
+  if (os_env_exists("__NVIM_TEST_LOG")) {
+    ELOG("test log message");
+  }
+
   // os_exit() will be invoked when the client channel detaches
   while (true) {
     LOOP_PROCESS_EVENTS(&main_loop, resize_events, -1);

src/nvim/ui_client.h

@@ -14,7 +14,7 @@ EXTERN size_t grid_line_buf_size INIT( = 0);
 EXTERN schar_T *grid_line_buf_char INIT( = NULL);
 EXTERN sattr_T *grid_line_buf_attr INIT( = NULL);
 
-// ID of the ui client channel. If zero, the client is not running.
+// Client-side UI channel. Zero during early startup or if not a (--remote-ui) UI client.
 EXTERN uint64_t ui_client_channel_id INIT( = 0);
 
 // exit status from embedded nvim process

test/functional/core/log_spec.lua

@@ -1,5 +1,6 @@
 local t = require('test.testutil')
 local n = require('test.functional.testnvim')()
+local tt = require('test.functional.terminal.testutil')
 
 local assert_log = t.assert_log
 local clear = n.clear
@@ -29,10 +30,54 @@ describe('log', function()
     assert(request('nvim__stats').log_skip <= 13)
   end)
 
-  it('messages are formatted with name or test id', function()
+  it('TUI client name is "ui"', function()
+    local function setup(env)
+      clear()
+      -- Start Nvim with builtin UI.
+      local screen = tt.setup_child_nvim({
+        '-u',
+        'NONE',
+        '-i',
+        'NONE',
+        '--cmd',
+        n.nvim_set,
+      }, {
+        env = env,
+      })
+      screen:expect([[
+        {1: }                                                 |
+        ~                                                 |*4
+                                                          |
+        {3:-- TERMINAL --}                                    |
+      ]])
+    end
+
+    -- Without $NVIM parent.
+    setup({
+      NVIM = '',
+      NVIM_LISTEN_ADDRESS = '',
+      NVIM_LOG_FILE = testlog,
+      __NVIM_TEST_LOG = '1',
+    })
+    -- Example:
+    --    ERR 2024-09-11T16:40:02.421 ui.47056   ui_client_run:165: test log message
+    assert_log(' ui%.%d+% +ui_client_run:%d+: test log message', testlog, 100)
+
+    -- With $NVIM parent.
+    setup({
+      NVIM_LOG_FILE = testlog,
+      __NVIM_TEST_LOG = '1',
+    })
+    -- Example:
+    --    ERR 2024-09-11T16:41:17.539 ui/c/T2.47826.0 ui_client_run:165: test log message
+    local tid = _G._nvim_test_id
+    assert_log(' ui/c/' .. tid .. '%.%d+%.%d +ui_client_run:%d+: test log message', testlog, 100)
+  end)
+
+  it('formats messages with session 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
+    --    ERR 2024-09-11T16:44:33.794 T3.49429.0 server_init:58: test log message
+    --    ERR 2024-09-11T16:44:33.823 c/T3.49429.0 server_init:58: test log message
 
     clear({
       env = {
@@ -47,10 +92,10 @@ describe('log', function()
 
     exec_lua([[
       local j1 = vim.fn.jobstart({ vim.v.progpath, '-es', '-V1', '+foochild', '+qa!' }, vim.empty_dict())
-      vim.fn.jobwait({ j1 }, 10000)
+      vim.fn.jobwait({ j1 }, 5000)
     ]])
 
-    -- Child Nvim spawned by jobstart() appends "/c" to parent name.
-    assert_log('%.%d+%.%d/c +server_init:%d+: test log message', testlog, 100)
+    -- Child Nvim spawned by jobstart() prepends "c/" to parent name.
+    assert_log('c/' .. tid .. '%.%d+%.%d +server_init:%d+: test log message', testlog, 100)
   end)
 end)