fix(editor): noisy :write Progress event #42456

Problem:
- Every :write emits a progress-message #41222. Progress events fire and
  terminals flash a progress spinner (OSC 9;4), even for a fast write.
- The "running" Progress event fires before `b_saving` is set, and the
  "failed" one after it is cleared, so a Progress handler could unload
  the buffer being written (use-after-free).

Solution:
- Emit a progress-message only if `:write` is slow (longer than 0.5s),
  otherwise emit only a "bufwrite" msg-kind.
- Clear `b_saving` after reporting errors.

Note: a Progress handler can still change the buffer text during a slow
write: the file gets mixed content, and 'modified' is reset anyway (no
memory corruption though).

runtime/doc/api-ui-events.txt

@@ -857,6 +857,7 @@ must handle.
 	    Name indicating the message kind. New kinds may be added in the
 	    future; clients should treat unknown kinds as the empty kind.
 	      • "" (empty): Unknown (consider a |feature-request|)
+	      • "bufwrite": |:write| message. If :write is slow it emits "progress".
 	      • "empty": Empty message (`:echo ""`), with empty `content`. Should
 	        clear messages sharing the 'cmdheight' area if it is the only
 	        message in a batch.
@@ -872,7 +873,7 @@ must handle.
 	      • "lua_print": |print()| from |:lua| code
 	      • "progress": Progress message emitted by |nvim_echo()|. Internal
 	        progress messages use these ids:
-		• `nvim.bufwrite "<filename>"`
+		• `nvim.bufwrite "<filename>"` (slow |:write|)
 		• `nvim.completion`
 		• `nvim.indent`
 	      • "quickfix": Quickfix navigation message

runtime/doc/news.txt

@@ -150,8 +150,8 @@ EVENTS
 • |vim.on_key()| callbacks are not invoked for keys consumed by |getchar()|.
 • |BufModifiedSet| has been removed. Use the |OptionSet| event with pattern
   "modified" instead.
-• |ui-messages| `msg_show.bufwrite` and `msg_show.completion` messages are now
-  `msg_show.progress` events.
+• |ui-messages| `msg_show.completion` messages are now `msg_show.progress`
+  events. If |:write| is slow it emits `msg_show.progress` events.
 
 LSP
 

src/nvim/bufwrite.c

@@ -43,6 +43,7 @@
 #include "nvim/os/fs_defs.h"
 #include "nvim/os/input.h"
 #include "nvim/os/os_defs.h"
+#include "nvim/os/time.h"
 #include "nvim/path.h"
 #include "nvim/pos_defs.h"
 #include "nvim/sha256.h"
@@ -66,6 +67,9 @@ static const char e_write_error_file_system_full[]
 static const char e_no_matching_autocommands_for_buftype_str_buffer[]
   = N_("E676: No matching autocommands for buftype=%s buffer");
 
+/// If :write is slower than this, emit a progress-message.
+static const uint64_t slow_write_ns = NS_PER_SEC / 2;
+
 typedef struct {
   const char *num;
   char *msg;
@@ -266,8 +270,7 @@ static int buf_write_convert(struct bw_info *ip, char **bufp, int *lenp)
   return wlen;
 }
 
-/// Call write() to write a number of bytes to the file.
-/// Handles 'encoding' conversion.
+/// Writes bytes to the file, converting from UTF-8 to 'fileencoding'.
 ///
 /// @return  FAIL for failure, OK otherwise.
 static int buf_write_bytes(struct bw_info *ip)
@@ -577,7 +580,7 @@ static void emit_err(Error_T *e, char *msg_id)
     xstrlcpy(errmsg, e->msg, IOSIZE);
   }
   if (msg_id != NULL) {
-    msg_progress(errmsg, msg_id, "failed", HLF_E, false, false, true);
+    msg_progress(errmsg, msg_id, "failed", -1, HLF_E, false, false, true);
   } else {
     emsg(errmsg);
   }
@@ -1106,13 +1109,17 @@ int buf_write(buf_T *buf, char *fname, char *sfname, linenr_T start, linenr_T en
   msg_id[strlen(msg_id) - 1] = NUL;  // add_quoted_fname() appends a space, for display only.
 
   // Hide the cursor until done writing, else it jumps to the filename message. #25974
-  const bool hide_cursor = !filtering && msg_silent == 0;
-  if (hide_cursor) {
+  const bool show_msg = !filtering && msg_silent == 0;
+  if (show_msg) {
     ui_busy_start();
   }
   if (!filtering) {
-    filemess_progress(buf, msgname, msg_id);
+    filemess_bufwrite(buf, msgname, msg_id);
   }
+
+  int progress = -1;  // Progress-message percent for a slow write.
+  off_T progress_nchars = 0;  // `nchars` at the last progress check.
+  const uint64_t write_start = os_hrtime();
   msg_scroll = false;               // always overwrite the file message now
 
   char *buffer = verbose_try_malloc(WRITEBUFSIZE);
@@ -1458,6 +1465,9 @@ restore_backup:
     write_info.bw_flags = wb_flags;
     fileformat = get_fileformat_force(buf, eap);
     char *s = buffer;
+
+    // The write loop: copies each line (plus EOL) into `buffer`, which buf_write_bytes() writes to
+    // the file whenever it is full (`bufsize`). Also reports progress.
     for (lnum = start; lnum <= end; lnum++) {
       // The next while loop is done once for each character written.
       // Keep it fast!
@@ -1526,7 +1536,19 @@ restore_backup:
           break;
         }
       }
+
+      // Show a progress-message (with updated %) if slow.
+      if (show_msg && nchars != progress_nchars) {
+        progress_nchars = nchars;
+        const int percent = (int)((int64_t)(lnum - start) * 100 / (end - start + 1));
+        if (percent != progress && (progress >= 0 || os_hrtime() - write_start > slow_write_ns)) {
+          progress = percent;
+          add_quoted_fname(IObuff, IOSIZE, buf, msgname);
+          msg_progress(IObuff, msg_id, "running", progress, 0, false, true, false);
+        }
+      }
     }
+
     if (write_info.bw_len > 0 && end > 0) {
       int remaining = write_info.bw_len;
       if (buf_write_bytes(&write_info) == FAIL) {
@@ -1732,7 +1754,9 @@ restore_backup:
         xstrlcat(IObuff, shortmess(kShmWri) ? _(" [w]") : _(" written"), IOSIZE);
       }
     }
-    set_keep_msg(msg_progress(IObuff, msg_id, "success", 0, true, true, false), 0);
+    set_keep_msg(progress >= 0
+                 ? msg_progress(IObuff, msg_id, "success", -1, 0, true, true, false)
+                 : msg_with_id(IObuff, msg_id, "bufwrite", NULL, 0, true, true, false), 0);
   }
 
   // When written everything correctly: reset 'modified'.  Unless not
@@ -1814,13 +1838,10 @@ restore_backup:
 fail:
   no_wait_return--;             // may wait for return now
 nofail:
-  if (hide_cursor) {
+  if (show_msg) {
     ui_busy_stop();
   }
 
-  // Done saving, we accept changed buffer warnings again
-  buf->b_saving = false;
-
   xfree(backup);
   if (buffer != smallbuf) {
     xfree(buffer);
@@ -1836,8 +1857,7 @@ nofail:
   if (err.msg != NULL) {
     // - 100 to save some space for further error message.
     add_quoted_fname(IObuff, IOSIZE - 100, buf, msgname);
-    // The error ends the progress-msg started by filemess_progress().
-    emit_err(&err, filtering ? NULL : msg_id);
+    emit_err(&err, progress >= 0 ? msg_id : NULL);
 
     retval = FAIL;
     if (end == 0) {
@@ -1854,6 +1874,9 @@ nofail:
       }
     }
   }
+
+  // Done saving, reported any errors. Allow "changed buffer" warnings and unloading `buf`, again.
+  buf->b_saving = false;
   msg_scroll = msg_save;
 
   // When writing the whole file and 'undofile' is set, also write the undo

src/nvim/fileio.c

@@ -111,8 +111,7 @@ static const char *e_auchangedbuf = N_("E812: Autocommands changed buffer or buf
 /// Shows a message about file `name`, e.g. `"foo.txt" [New]`.
 ///
 /// @param s Info appended to the filename, e.g. "[New]".
-/// @param msg_id Emit as a progress-message with this id, or NULL for a plain message.
-///               Caller must emit a non-"running" status for `msg_id`, later.
+/// @param msg_id Emit as a "bufwrite" message with this id, or NULL for a plain message.
 static void filemess(buf_T *buf, char *name, char *s, const char *msg_id)
 {
   int prev_msg_col = msg_col;
@@ -144,7 +143,7 @@ static void filemess(buf_T *buf, char *name, char *s, const char *msg_id)
   msg_scrolled_ign = true;
   // may truncate the message to avoid a hit-return prompt
   if (msg_id != NULL) {
-    msg_progress(IObuff, (char *)msg_id, "running", 0, false, true, false);
+    msg_with_id(IObuff, (char *)msg_id, "bufwrite", NULL, 0, false, true, false);
   } else {
     msg_outtrans(msg_may_trunc(false, IObuff), 0, false);
   }
@@ -152,9 +151,9 @@ static void filemess(buf_T *buf, char *name, char *s, const char *msg_id)
   msg_scrolled_ign = false;
 }
 
-/// Shows the "busy" message for writing file `name`, as a progress-message. #39280
-/// Caller must end the progress by emitting a non-"running" status to the same `msg_id`.
-void filemess_progress(buf_T *buf, char *name, const char *msg_id)
+/// Shows file `name` before writing it, as a "bufwrite" message with `msg_id`, which buf_write()
+/// replaces when done (or with a progress-message, if slow).
+void filemess_bufwrite(buf_T *buf, char *name, const char *msg_id)
 {
   filemess(buf, name, "", msg_id);
 }

src/nvim/indent.c

@@ -953,7 +953,7 @@ void op_reindent(oparg_T *oap, Indenter how)
         // Restore cursor to avoid redrawing curwin in msg_show callback.
         linenr_T save_lnum = curwin->w_cursor.lnum;
         curwin->w_cursor.lnum = start_lnum;
-        msg_progress(IObuff, "nvim.indent", "running", 0, true, false, false);
+        msg_progress(IObuff, "nvim.indent", "running", -1, 0, true, false, false);
         curwin->w_cursor.lnum = save_lnum;
       }
 
@@ -995,7 +995,7 @@ void op_reindent(oparg_T *oap, Indenter how)
     i = oap->line_count - (i + 1);
     snprintf(IObuff, IOSIZE,
              NGETTEXT("%" PRId64 " line indented ", "%" PRId64 " lines indented ", i), (int64_t)i);
-    msg_progress(IObuff, "nvim.indent", "success", 0, true, false, false);
+    msg_progress(IObuff, "nvim.indent", "success", -1, 0, true, false, false);
   }
   if ((cmdmod.cmod_flags & CMOD_LOCKMARKS) == 0) {
     // set '[ and '] marks

src/nvim/insexpand.c

@@ -2110,7 +2110,7 @@ static void ins_compl_files(int count, char **files, bool thesaurus, int flags,
     FILE *fp = os_fopen(files[i], "r");  // open dictionary file
     if (flags != DICT_EXACT && !shortmess(kShmCompletionscan) && !compl_autocomplete) {
       vim_snprintf(IObuff, IOSIZE, _("Scanning dictionary: %s"), files[i]);
-      msg_progress(IObuff, "nvim.completion", "running", HLF_R, false, true, false);
+      msg_progress(IObuff, "nvim.completion", "running", -1, HLF_R, false, true, false);
     }
 
     if (fp == NULL) {
@@ -3961,7 +3961,7 @@ static int process_next_cpt_value(ins_compl_next_state_T *st, int *compl_type_ar
                    : st->ins_buf->b_sfname == NULL
                    ? st->ins_buf->b_fname
                    : st->ins_buf->b_sfname);
-      msg_progress(IObuff, "nvim.completion", "running", HLF_R, false, true, false);
+      msg_progress(IObuff, "nvim.completion", "running", -1, HLF_R, false, true, false);
     }
   } else if (*st->e_cpt == NUL) {
     status = INS_COMPL_CPT_END;
@@ -3995,7 +3995,7 @@ static int process_next_cpt_value(ins_compl_next_state_T *st, int *compl_type_ar
         compl_type = CTRL_X_TAGS;
         if (!shortmess(kShmCompletionscan) && !compl_autocomplete) {
           vim_snprintf(IObuff, IOSIZE, "%s", _("Scanning tags."));
-          msg_progress(IObuff, "nvim.completion", "running", HLF_R, false, true, false);
+          msg_progress(IObuff, "nvim.completion", "running", -1, HLF_R, false, true, false);
         }
       }
     }
@@ -6426,7 +6426,7 @@ int ins_complete(int c, bool enable_pum)
 
   if (!shortmess(kShmCompletionscan) && !compl_autocomplete) {
     // End the "Scanning..." progress-msg. ins_compl_show_statusmsg() already reported the result.
-    msg_progress(NULL, "nvim.completion", "success", 0, false, false, false);
+    msg_progress(NULL, "nvim.completion", "success", -1, 0, false, false, false);
   }
 
   // Show the popup menu, unless we got interrupted.

src/nvim/message.c

@@ -1111,16 +1111,30 @@ char *msg_may_trunc(bool force, char *s)
 /// Shows a progress-message.  A non-"running" `status` ends the message and announces the
 /// progress task as "done".
 ///
-/// @param s    Message text.  NULL ends the message without showing anything.
-/// @param err  Show as an error message.
-char *msg_progress(char *s, char *id, char *status, int hl_id, bool hist, bool trunc, bool err)
+/// @param s        Message text.  NULL ends the message without showing anything.
+/// @param percent  Progress percentage, or -1 if unknown.
+/// @param err      Show as an error message.
+char *msg_progress(char *s, char *id, char *status, int percent, int hl_id, bool hist, bool trunc,
+                   bool err)
 {
-  bool clear = false;
   MessageData data = {
     .source = cstr_as_string("nvim"),
     .status = cstr_as_string(status),
-    .percent = -1,
+    .percent = percent,
   };
+  return msg_with_id(s, id, "progress", &data, hl_id, hist, trunc, err);
+}
+
+/// Shows message `s` with `id`: replaces the message with the same `id`, if any.
+///
+/// @param s     Message text.  NULL ends a progress-message without showing anything.
+/// @param kind  Message kind, e.g. "progress".
+/// @param data  Progress-message data, or NULL.
+/// @param err   Show as an error message.
+char *msg_with_id(char *s, char *id, const char *kind, MessageData *data, int hl_id, bool hist,
+                  bool trunc, bool err)
+{
+  bool clear = false;
   HlMessage chunks = KV_INITIAL_VALUE;
   if (s != NULL) {
     if (hist && (!trunc || ui_has(kUIMessages))) {
@@ -1132,7 +1146,7 @@ char *msg_progress(char *s, char *id, char *status, int hl_id, bool hist, bool t
     kv_push(chunks, ((HlMessageChunk){ cstr_as_string(s), hl_id }));
   }
   msg_ext_no_fast();
-  msg_multihl(CSTR_AS_OBJ(id), chunks, "progress", false, err, &data, &clear, false);
+  msg_multihl(CSTR_AS_OBJ(id), chunks, kind, false, err, data, &clear, false);
   kv_destroy(chunks);
   ui_flush();
   return s;

test/functional/ui/messages2_spec.lua

@@ -1190,7 +1190,8 @@ describe('messages2', function()
 
   it('configured targets per kind', function()
     exec_lua(function()
-      local targets = { echo = 'msg', list_cmd = 'pager', bufwrite = 'cmd', lua_print = 'cmd' }
+      local targets = { echo = 'msg', list_cmd = 'pager', lua_print = 'cmd' }
+      targets['nvim%.bufwrite'] = 'msg' -- Matches the message ID, not the kind.
       require('vim._core.ui2').enable({ msg = { targets = targets } })
       print('foo') -- "lua_print" kind goes to cmd
       vim.cmd.echo('"bar"') -- "echo" kind goes to msg
@@ -1230,9 +1231,10 @@ describe('messages2', function()
     command('edit Xfile | write')
     screen:expect([[
       ^                                                     |
-      {1:~                                                    }|*11
-      {1:~                                              }{4:bar(2)}|
-      "Xfile" [New] 0L, 0B written                         |
+      {1:~                                                    }|*10
+      {1:~                        }{4:bar                         }|
+      {1:~                        }{4:"Xfile" [New] 0L, 0B written}|
+      foo(1)                                               |
     ]])
   end)
 

test/functional/ui/messages_spec.lua

@@ -100,7 +100,7 @@ describe('ui/ext_messages', function()
           content = { { writemsg } },
           history = true,
           id = 'nvim.bufwrite "Xtest_functional_ui_messages_spec"',
-          kind = 'progress',
+          kind = 'bufwrite',
         },
         {
           content = { { 'W10: Warning: Changing a readonly file', 19, 'WarningMsg' } },
@@ -1408,7 +1408,7 @@ stack traceback:
       messages = {
         {
           content = { { string.format('"%s" [New] 0L, 0B written', fname) } },
-          kind = 'progress',
+          kind = 'bufwrite',
           id = 'nvim.bufwrite "Xtest_functional_ui_messages_spec"',
           history = true,
         },
@@ -3934,39 +3934,51 @@ describe('progress-message', function()
     })
   end)
 
-  it('emitted by :write, not by :read #41193', function()
+  it('emitted by slow :write, but not :read #41193 #41713', function()
+    t.skip(t.is_os('win'), 'N/A for Windows') -- Using mkfifo to simulate slow :write.
     local fname = 'Xtest_progress_bufwrite'
     finally(function()
       os.remove(fname)
     end)
-    command('write ' .. fname)
-    assert_progress_autocmd({
-      data = {},
-      id = ('nvim.bufwrite "%s"'):format(fname),
-      source = 'nvim',
-      status = 'success',
-      text = { ('"%s" [New] 0L, 0B written'):format(fname) },
-      title = '',
-    })
 
-    -- ":read" is not a write: it must not start a progress that never ends.
+    -- ":write" faster than `slow_write_ns` does not emit a progress-msg.
+    command('write ' .. fname)
+    assert_progress_autocmd(nil)
+
+    -- ":read" does not emit a progress-msg.
     command('read ' .. fname)
     assert_progress_autocmd(nil)
 
-    -- A failed write ends the progress-msg.
-    local events = exec_lua(function(f)
-      local out = {}
-      vim.api.nvim_create_autocmd('Progress', {
-        callback = function(ev)
-          table.insert(out, { id = ev.data.id, status = ev.data.status, text = ev.data.text[1] })
-        end,
-      })
-      pcall(vim.cmd.write, ('%s/nodir'):format(f))
-      return out
-    end, fname)
-    eq({ 'running', 'failed' }, { events[1].status, events[2].status })
-    eq(events[1].id, events[2].id)
-    t.matches('^E%d+:', events[2].text)
+    os.remove(fname)
+    fn.system({ 'mkfifo', fname })
+
+    --- Slow :write. Simulated by writing to a fifo, read by `reader` after > `slow_write_ns`.
+    local function slow_write(reader)
+      return exec_lua(function(f, cmd)
+        local out = {}
+        vim.api.nvim_create_autocmd('Progress', {
+          callback = function(ev)
+            table.insert(out, ev.data.status)
+            -- :bwipeout disallowed (E937) while writing.
+            out.wiped = out.wiped or pcall(vim.cmd.bwipe, { bang = true })
+          end,
+        })
+        vim.api.nvim_buf_set_lines(0, 0, -1, true, vim.fn['repeat']({ ('x'):rep(99) }, 2000))
+        local proc = vim.system({
+          'sh',
+          '-c',
+          ('exec 3<"$1"; sleep 0.6; %s <&3 >/dev/null'):format(cmd),
+          'sh',
+          f,
+        })
+        local ok, err = pcall(vim.cmd.write, { f, bang = true })
+        proc:wait()
+        return { out[1], out[#out], out.wiped, ok and 'ok' or err:match('E%d+') }
+      end, fname, reader)
+    end
+
+    eq({ 'running', 'success', false, 'ok' }, slow_write('cat'))
+    eq({ 'running', 'failed', false, 'E514' }, slow_write('head -c 100000')) -- Write error (EPIPE).
   end)
 
   it('emitted by ins-completion scan', function()