fix(log): unify error messages for vim.ui_attach/decor providers #33005

Problem:  Error messages that cause a vim.ui_attach() namespace to
          detach are not visible in the message history. Decoration
          provider and vim.ui_attach error messages are dissimilar.
Solution: Emit vim.ui_attach() errors as an actual message in addition
          to logging it. Adjust error message format.

src/nvim/decoration_provider.c

@@ -23,8 +23,6 @@
 # include "decoration_provider.c.generated.h"
 #endif
 
-enum { DP_MAX_ERROR = 3, };
-
 static kvec_t(DecorProvider) decor_providers = KV_INITIAL_VALUE;
 
 #define DECORATION_PROVIDER_INIT(ns_id) (DecorProvider) \
@@ -34,9 +32,9 @@ static kvec_t(DecorProvider) decor_providers = KV_INITIAL_VALUE;
 
 static void decor_provider_error(DecorProvider *provider, const char *name, const char *msg)
 {
-  const char *ns_name = describe_ns(provider->ns_id, "(UNKNOWN PLUGIN)");
+  const char *ns = describe_ns(provider->ns_id, "(UNKNOWN PLUGIN)");
-  ILOG("error in provider %s.%s: %s", ns_name, name, msg);
+  ELOG("Error in decoration provider \"%s\" (ns=%s):\n%s", name, ns, msg);
-  msg_schedule_semsg_multiline("Error in decoration provider %s.%s:\n%s", ns_name, name, msg);
+  msg_schedule_semsg_multiline("Error in decoration provider \"%s\" (ns=%s):\n%s", name, ns, msg);
 }
 
 // Note we pass in a provider index as this function may cause decor_providers providers to be
@@ -59,11 +57,11 @@ static bool decor_provider_invoke(int provider_idx, const char *name, LuaRef ref
     return true;
   }
 
-  if (ERROR_SET(&err) && provider->error_count < DP_MAX_ERROR) {
+  if (ERROR_SET(&err) && provider->error_count < CB_MAX_ERROR) {
     decor_provider_error(provider, name, err.msg);
     provider->error_count++;
 
-    if (provider->error_count >= DP_MAX_ERROR) {
+    if (provider->error_count >= CB_MAX_ERROR) {
       provider->state = kDecorProviderDisabled;
     }
   }

src/nvim/lua/executor.h

@@ -44,6 +44,9 @@ typedef enum {
   kRetLuaref,  ///< return value becomes a single Luaref, regardless of type (except NIL)
 } LuaRetMode;
 
+/// Maximum number of errors in vim.ui_attach() and decor provider callbacks.
+enum { CB_MAX_ERROR = 3, };
+
 /// To use with kRetNilBool for quick truthiness check
 #define LUARET_TRUTHY(res) ((res).type == kObjectTypeBoolean && (res).data.boolean == true)
 

src/nvim/ui.c

@@ -6,6 +6,7 @@
 #include <string.h>
 #include <uv.h>
 
+#include "nvim/api/extmark.h"
 #include "nvim/api/private/helpers.h"
 #include "nvim/api/private/validate.h"
 #include "nvim/api/ui.h"
@@ -712,6 +713,13 @@ void ui_grid_resize(handle_T grid_handle, int width, int height, Error *err)
   }
 }
 
+static void ui_attach_error(uint32_t ns_id, const char *name, const char *msg)
+{
+  const char *ns = describe_ns((NS)ns_id, "(UNKNOWN PLUGIN)");
+  ELOG("Error in \"%s\" UI event handler (ns=%s):\n%s", name, ns, msg);
+  msg_schedule_semsg_multiline("Error in \"%s\" UI event handler (ns=%s):\n%s", name, ns, msg);
+}
+
 void ui_call_event(char *name, bool fast, Array args)
 {
   bool handled = false;
@@ -735,7 +743,7 @@ void ui_call_event(char *name, bool fast, Array args)
       handled = true;
     }
     if (ERROR_SET(&err)) {
-      ELOG("Error executing UI event callback: %s", err.msg);
+      ui_attach_error(ns_id, name, err.msg);
       ui_remove_cb(ns_id, true);
     }
     api_clear_error(&err);
@@ -792,13 +800,14 @@ void ui_add_cb(uint32_t ns_id, LuaRef cb, bool *ext_widgets)
 void ui_remove_cb(uint32_t ns_id, bool checkerr)
 {
   UIEventCallback *item = pmap_get(uint32_t)(&ui_event_cbs, ns_id);
-  if (item && (!checkerr || ++item->errors > 10)) {
+  if (item && (!checkerr || ++item->errors > CB_MAX_ERROR)) {
     pmap_del(uint32_t)(&ui_event_cbs, ns_id, NULL);
     free_ui_event_callback(item);
     ui_cb_update_ext();
     ui_refresh();
     if (checkerr) {
-      msg_schedule_semsg("Excessive errors in vim.ui_attach() callback from ns: %d.", ns_id);
+      const char *ns = describe_ns((NS)ns_id, "(UNKNOWN PLUGIN)");
+      msg_schedule_semsg("Excessive errors in vim.ui_attach() callback (ns=%s)", ns);
     }
   }
 }

test/functional/lua/ui_event_spec.lua

@@ -32,6 +32,7 @@ describe('vim.ui_attach', function()
     ]]
 
     screen = Screen.new(40, 5)
+    screen:add_extra_attr_ids({ [100] = { bold = true, foreground = Screen.colors.SeaGreen } })
   end)
 
   local function expect_events(expected)
@@ -215,7 +216,7 @@ describe('vim.ui_attach', function()
       },
       messages = {
         {
-          content = { { '\nSave changes?\n', 6, 10 } },
+          content = { { '\nSave changes?\n', 100, 10 } },
           history = false,
           kind = 'confirm',
         },
@@ -315,51 +316,41 @@ describe('vim.ui_attach', function()
       },
     })
   end)
-end)
-
-describe('vim.ui_attach', function()
-  local screen
-  before_each(function()
-    clear({ env = { NVIM_LOG_FILE = testlog } })
-    screen = Screen.new(40, 5)
-  end)
-
-  after_each(function()
-    check_close()
-    os.remove(testlog)
-  end)
-
-  it('error in callback is logged', function()
-    exec_lua([[
-      local ns = vim.api.nvim_create_namespace('testspace')
-      vim.ui_attach(ns, { ext_popupmenu = true }, function() error(42) end)
-    ]])
-    feed('ifoo<CR>foobar<CR>fo<C-X><C-N>')
-    assert_log('Error executing UI event callback: Error executing lua: .*: 42', testlog, 100)
-  end)
 
   it('detaches after excessive errors', function()
-    screen:add_extra_attr_ids({ [100] = { bold = true, foreground = Screen.colors.SeaGreen } })
+    screen:try_resize(86, 10)
     exec_lua([[
-      vim.ui_attach(vim.api.nvim_create_namespace(''), { ext_messages = true }, function()
+      vim.ui_attach(vim.api.nvim_create_namespace(''), { ext_messages = true }, function(ev)
+        if ev:find('msg') then
           vim.api.nvim_buf_set_lines(0, -2, -1, false, { err[1] })
+        end
       end)
       ]])
     local s1 = [[
       ^                                                                                      |
-      {1:~                                       }|*4
+      {1:~                                                                                     }|*9
     ]]
     screen:expect(s1)
-    feed('QQQQQQ<CR>')
+    feed('Q<CR>')
     screen:expect({
-      grid = [[
+      grid = s1,
-        {9:obal 'err' (a nil value)}                |
-        {9:stack traceback:}                        |
-        {9:        [string "<nvim>"]:2: in function}|
-        {9: <[string "<nvim>"]:1>}                  |
-        {100:Press ENTER or type command to continue}^ |
-      ]],
       messages = {
+        {
+          content = { { "E354: Invalid register name: '^@'", 9, 6 } },
+          history = true,
+          kind = 'emsg',
+        },
+        {
+          content = {
+            {
+              'Error executing callback:\n[string "<nvim>"]:3: attempt to index global \'err\' (a nil value)\nstack traceback:\n\t[string "<nvim>"]:3: in function <[string "<nvim>"]:1>',
+              9,
+              6,
+            },
+          },
+          history = true,
+          kind = 'lua_error',
+        },
         {
           content = { { 'Press ENTER or type command to continue', 100, 18 } },
           history = false,
@@ -367,15 +358,21 @@ describe('vim.ui_attach', function()
         },
       },
     })
-    feed(':1mes clear<CR>:mes<CR>')
+    feed('<CR>:messages<CR>')
     screen:expect([[
-                                              |
+      {9:Error in "msg_show" UI event handler (ns=(UNKNOWN PLUGIN)):}                           |
-      {3:                                        }|
+      {9:Error executing lua: [string "<nvim>"]:3: attempt to index global 'err' (a nil value)} |
-      {9:Excessive errors in vim.ui_attach() call}|
+      {9:stack traceback:}                                                                      |
-      {9:back from ns: 2.}                        |
+      {9:        [string "<nvim>"]:3: in function <[string "<nvim>"]:1>}                        |
+      {9:Error in "msg_clear" UI event handler (ns=(UNKNOWN PLUGIN)):}                          |
+      {9:Error executing lua: [string "<nvim>"]:3: attempt to index global 'err' (a nil value)} |
+      {9:stack traceback:}                                                                      |
+      {9:        [string "<nvim>"]:3: in function <[string "<nvim>"]:1>}                        |
+      {9:Excessive errors in vim.ui_attach() callback (ns=(UNKNOWN PLUGIN))}                    |
       {100:Press ENTER or type command to continue}^                                               |
     ]])
-    feed('<cr>')
+    feed('<CR>')
+
     -- Also when scheduled
     exec_lua([[
       vim.ui_attach(vim.api.nvim_create_namespace(''), { ext_messages = true }, function()
@@ -414,15 +411,34 @@ describe('vim.ui_attach', function()
         },
       },
     })
-    feed('<esc>:1mes clear<cr>:mes<cr>')
+    feed('<Esc>:1messages clear<cr>:messages<CR>')
     screen:expect([[
-                                              |
+      ^                                                                                      |
-      {3:                                        }|
+      {1:~                                                                                     }|*8
-      {9:Excessive errors in vim.ui_attach() call}|
+      {9:Excessive errors in vim.ui_attach() callback (ns=(UNKNOWN PLUGIN))}                    |
-      {9:back from ns: 3.}                        |
-      {100:Press ENTER or type command to continue}^ |
     ]])
   end)
+end)
+
+describe('vim.ui_attach', function()
+  before_each(function()
+    clear({ env = { NVIM_LOG_FILE = testlog } })
+  end)
+
+  after_each(function()
+    check_close()
+    os.remove(testlog)
+  end)
+
+  it('error in callback is logged', function()
+    exec_lua([[
+      local ns = vim.api.nvim_create_namespace('test')
+      vim.ui_attach(ns, { ext_popupmenu = true }, function() error(42) end)
+    ]])
+    feed('ifoo<CR>foobar<CR>fo<C-X><C-N>')
+    assert_log('Error in "popupmenu_show" UI event handler %(ns=test%):', testlog, 100)
+    assert_log('Error executing lua: .*: 42', testlog, 100)
+  end)
 
   it('sourcing invalid file does not crash #32166', function()
     exec_lua([[

test/functional/ui/decorations_spec.lua

@@ -759,6 +759,7 @@ describe('decorations providers', function()
   end)
 
   it('errors gracefully', function()
+    screen:try_resize(65, screen._height)
     insert(mulholland)
 
     setup_provider [[
@@ -767,16 +768,16 @@ describe('decorations providers', function()
     end
     ]]
 
-    screen:expect{grid=[[
+    screen:expect([[
-      {2:Error in decoration provider ns1.start:} |
+      // just to see if there was an accident                          |
-      {2:Error executing lua: [string "<nvim>"]:4}|
+      {8:                                                                 }|
-      {2:: Foo}                                   |
+      {2:Error in decoration provider "start" (ns=ns1):}                   |
+      {2:Error executing lua: [string "<nvim>"]:4: Foo}                    |
       {2:stack traceback:}                                                 |
       {2:        [C]: in function 'error'}                                 |
-      {2:        [string "<nvim>"]:4: in function}|
+      {2:        [string "<nvim>"]:4: in function <[string "<nvim>"]:3>}   |
-      {2: <[string "<nvim>"]:3>}                  |
       {18:Press ENTER or type command to continue}^                          |
-    ]]}
+    ]])
   end)
 
   it('can add new providers during redraw #26652', function()