djcb
Bug: update timer can kill the update buffer for the next update
Expected or desired behavior
When something goes wrong updating email, I should not get a prompt or lots of errors.
Actual behavior
Sometimes, I get a prompt warning me that *mu4e-update* has an active process, do I want to kill it? This is a y-or-n-p prompt. Sometimes there are several of these (I have to smash 'n' for 5 minutes). Mostly, this happens under load or when coming out of suspend.
Steps to reproduce
- Enable the mu4e update timer, by setting
mu4e~update-interval. Make it relatively fast. - Wait. It'll happen.
Versions of mu, mu4e/emacs, operating system etc.
1.0, 26.1, Mac OSX.
Any other detail
Well, I know what the problem is. Due to legal nonsense, I can't (yet) submit a pull request, so I'll do what I can here to describe it:
The timer task doesn't trigger another update if one is already running:
(defun mu4e-update-mail-and-index (run-in-background)
;; ....
if (and (buffer-live-p mu4e~update-buffer)
(process-live-p (get-buffer-process mu4e~update-buffer)))
(mu4e-message "Update process is already running")
However, when things go wrong, we use sit-for:
(defun mu4e~update-sentinel-func (proc msg)
;; ....
(if (or (not (eq (process-status proc) 'exit))
(/= (process-exit-status proc) 0))
(progn
(when mu4e-index-update-error-warning
(mu4e-message "Update process returned with non-zero exit code")
(sit-for 5))
At this point, if the timer fires again the buffer is alive but the process is not. So it will trigger another update. After the sitting ends, the sentinel for the dead process resumes and tries to cleanup:
(when (buffer-live-p mu4e~update-buffer)
(unless (eq mu4e-split-view 'single-window)
(mapc #'delete-window (get-buffer-window-list mu4e~update-buffer)))
(kill-buffer mu4e~update-buffer)))))
The buffer will be alive at this point, so we'll try kill it. But we have a new process running. kill-buffer says:
The functions in ‘kill-buffer-query-functions’ are called with the buffer to be killed as the current buffer.
For me, it is set:
kill-buffer-query-functions is a variable defined in ‘buffer.c’. Its value is (process-kill-buffer-query-function)
This is where my prompt comes from. The prompt is just a symptom, though. It is actually wrong to kill the buffer at this point.
Here is a reasonable (I think) fix:
(when (buffer-live-p mu4e~update-buffer)
(unless (eq mu4e-split-view 'single-window)
(mapc #'delete-window (get-buffer-window-list mu4e~update-buffer)))
- (kill-buffer mu4e~update-buffer)))
+ (unless (get-buffer-process mu4e~update-buffer)
+ (kill-buffer mu4e~update-buffer))))
In a way, this is just a workaround. A better way would be to flip a single boolean that states the timer task can refire. But I haven't tested/tried that.
Here is a more complete diff of what I currently have:
modified mu4e/mu4e-utils.el
@@ -839,8 +839,15 @@ Checks whether the server process is live."
;;
(defvar mu4e~update-timer nil
"The mu4e update timer.")
+
(defconst mu4e~update-name "*mu4e-update*"
"Name of the process and buffer to update mail.")
+(defconst mu4e~update-log-buffer-name "*mu4e-update-log*"
+ "Update log. This buffer lists the results of update processes. Useful for debugging.")
+(defcustom mu4e~update-log-enabled nil
+ "If true, enable the update log."
+ :type 'boolean)
+
(defconst mu4e~update-buffer-height 8
"Height of the mu4e message retrieval/update buffer.")
@@ -1006,15 +1013,51 @@ frame to display buffer BUF."
(/= (process-exit-status proc) 0))
(progn
(when mu4e-index-update-error-warning
+ (mu4e~update-log proc "FAIL" "update process failed: %s" msg)
(mu4e-message "Update process returned with non-zero exit code")
(sit-for 5))
(when mu4e-index-update-error-continue
(mu4e-update-index)))
+ (mu4e~update-log proc "DONE" "update process finished: %s" msg)
(mu4e-update-index))
(when (buffer-live-p mu4e~update-buffer)
(unless (eq mu4e-split-view 'single-window)
(mapc #'delete-window (get-buffer-window-list mu4e~update-buffer)))
- (kill-buffer mu4e~update-buffer)))
+ (let ((proc-alive (get-buffer-process mu4e~update-buffer)))
+ (if proc-alive
+ (mu4e~update-log proc "BUG" "KILL-BUFFER" "unexpected proc found: %s" (process-id proc-alive))
+ (kill-buffer mu4e~update-buffer)))))
+
+(defun mu4e~update-log (proc message-type message &rest args)
+ "Log a message to `mu4e~update-log-buffer-name' if `mu4e~update-log-enabled' is set.
+
+The purpose of the update log is to understand when mu4e
+schedules updates (of your mailbox and index) and whether they
+succeed or not. This can be useful when debugging mu4e itself.
+
+The log entry will be a single line with the current timestamp,
+details about the process being run, and more specific
+message. If ARGS are present, they will be formatted into the
+message with `format'.
+
+MESSAGE-TYPE can be anything, but the idea is to disambiguate
+types of entries so that the buffer is easier to scan/filter."
+ (when mu4e~update-log-enabled
+ (save-excursion
+ (with-current-buffer (get-buffer-create mu4e~update-log-buffer-name)
+ (read-only-mode)
+ (let ((inhibit-read-only t))
+ (end-of-buffer)
+ (insert (current-time-string))
+ (insert " ")
+ (insert (format "%8s" message-type))
+ (insert " ")
+ (insert (format "%s [pid=%s, status=%4s, code=%s] "
+ (process-name proc) (process-id proc)
+ (symbol-name (process-status proc))
+ (process-exit-status proc)))
+ (insert (format message args))
+ (insert "\n"))))))
;; complicated function, as it:
;; - needs to check for errors
@@ -1031,6 +1074,7 @@ run in the background; otherwise, pop up a window."
(buf (process-buffer proc))
(win (or run-in-background
(mu4e~temp-window buf mu4e~update-buffer-height))))
+ (mu4e~update-log proc "START" "update process started: %s" mu4e-get-mail-command)
(setq mu4e~update-buffer buf)
(when (window-live-p win)
(with-selected-window win
When the bug triggers, my update log says:
Mon Aug 13 20:36:49 2018 START mu4e-update [pid=11856, status= run, code=0] update process started: (mbsync -q)
Mon Aug 13 22:04:52 2018 FAIL mu4e-update [pid=11856, status=exit, code=1] update process failed: (exited abnormally with code 1
)
Mon Aug 13 23:52:33 2018 START mu4e-update [pid=12048, status= run, code=0] update process started: (mbsync -q)
Mon Aug 13 23:52:33 2018 BUG mu4e-update [pid=11856, status=exit, code=1] KILL-BUFFER
Mon Aug 13 23:53:03 2018 FAIL mu4e-update [pid=12048, status=exit, code=1] update process failed: (exited abnormally with code 1
Can't reproduce this, even with
(setq mu4e-get-mail-command "false"
mu4e-update-interval 1)
