bug#73041: 30.0.90; track-changes-mode logs warnings (#70541 regression? not actually fixed?)

[Eli Zaretskii <eliz@gnu.org>]

Ping! epg, could you please try Stefan's patches and report back?

> From: Stefan Monnier <monnier@iro.umontreal.ca>
> Cc: epg@pretzelnet.org,  73041@debbugs.gnu.org
> Date: Sun, 08 Sep 2024 19:06:09 -0400
> 
> 
> >> I wish I could describe exactly what happened.  I found
> >> https://debbugs.gnu.org/cgi/bugreport.cgi?bug=70541 which sounds
> >> very much like what I'm seeing, but I don't use any input method.
> 
> Thanks for your description of the problem.  A reproducible recipe is of
> course better, but sadly, we can't always have what we want.
> Let's hope we find that eventually we'll get what we need.
> 
> >> Eventually, this pops into *Messages*:
> >> 
> >> #+begin_quote
> >> cl--assertion-failed: Assertion failed: (or track-changes--before-no (<=
> >> track-changes--before-beg (track-changes--state-beg track-changes--state)
> >> beg end (track-changes--state-end track-changes--state)
> >> track-changes--before-end))
> >> #+end_quote
> 
> Hmm... this clearly points to a bug in track-changes.
> 
> >> #+begin_quote
> >> ⛔ Warning (emacs): Missing/incorrect calls to ‘before/after-change-functions’!!
> >> Details logged to ‘track-changes--error-log’
> >> #+end_quote
> 
> Barring bugs in track-changes, this points to a bug in some other part
> of Emacs, which prevents track-changes from getting the info it needs.
> Track-changes (and Eglot) are supposedly equipped to deal with such
> problems, because we know we still have many of them.
> 
> >> Over time, they just keep repeating,
> 
> Hmm... `track-changes--recover-from-error` should (as the name suggests)
> "recover" so they shouldn't just keep repeating, unless the source of
> the problem keeps repeating as well.  Or unless there's a bug in
> track-changes.
> 
> >> although I think killing the
> >> buffer and reopening the file makes it stop.
> >>
> >> If I have inspected ‘track-changes--error-log’ correctly, this is
> >> what it contains (looks like some binary, hope it comes through
> >> in some useful fashion or another):
> 
> It's a list of debug info, one per "recovery".  Each debug info is made
> of the buffer name, the inconsistency encountered, then a backtrace, and
> an extract of (raw) `view-lossage`.  Here's your data reformatted:
> 
>     (("lib.rs" (buffer-size 5254 5218)
>       ((t track-changes--recover-from-error ... nil)
>        (t track-changes-fetch ... nil)
>        (t eglot--track-changes-fetch ... nil)
>        (t eglot--signal-textDocument/didChange nil nil)
>        (t eglot--signal-textDocument/didSave nil nil)
>        (t run-hooks ... nil)
>        (t basic-save-buffer ... nil)
>        (t save-buffer ... nil)
>        (t funcall-interactively ... nil)
>        (t call-interactively ... nil)
>        (t command-execute ... nil))
>       [111 (nil . other-window)
>        103 (nil . recompile)
>        121 (nil . undefined)
>        24 96 (nil . next-error)
>        1 (nil . move-beginning-of-line)
>        11 ...])
>      ("lib.rs" (buffer-size 5256 5254)
>       ((t track-changes--recover-from-error ... nil)
>        (t track-changes-fetch ... nil)
>        (t eglot--track-changes-fetch ... nil)
>        (t eglot--signal-textDocument/didChange nil nil)
>        (t eglot--signal-textDocument/didSave nil nil)
>        (t run-hooks ... nil)
>        (t basic-save-buffer ... nil)
>        (t save-buffer nil nil)
>        (t #[257 "r\211q\210\300 )\207" [save-buffer] 2 ...]
>        (t map-y-or-n-p ... nil)
>        (t save-some-buffers ... nil)
>        (t recompile ... nil)
>        ...)
>       [19 (nil . save-buffer)
>        24 24 (nil . exchange-point-and-mark)
>        23 (nil . kill-region)
>        24 19 (nil . save-buffer)
>        backspace (nil . delete-backward-char) ...])
>      ("lib.rs" (buffer-size 5278 5256)
>       ((t track-changes--recover-from-error ... nil)
>        (t track-changes-fetch ... nil)
>        (t eglot--track-changes-fetch ... nil)
>        (t eglot--signal-textDocument/didChange nil nil)
>        (t eglot--signal-textDocument/didSave nil nil)
>        (t run-hooks ... nil)
>        (t basic-save-buffer ... nil)
>        (t save-buffer ... nil)
>        (t funcall-interactively ... nil)
>        (t call-interactively ... nil)
>        (t command-execute ... nil))
>       [(nil . backward-word)
>        2 (nil . backward-char)
>        67108896 (nil . set-mark-command)
>        134217734 (nil . forward-sexp)
>        23 (nil . kill-region)
>        24 19 (nil . save-buffer)
>        ...])
>      ("lib.rs" (buffer-size 5324 5278)
>       ((t track-changes--recover-from-error ... nil)
>        (t track-changes-fetch ... nil)
>        (t eglot--track-changes-fetch ... nil)
>        (t eglot--track-changes-signal ... nil)
>        (t #[771 "\211^BZ\211^HG^E] ...)
>        ...)
>       ...)
>      ...)
> 
> This suggests the error is always detected "late" when we find that the
> buffer-size is not the one we expected, so some buffer change presumably
> happened without informing track-changes.
> That doesn't explain the assertion failure.
> 
> Also, I don't see anything "unusual" in the view-lossage.
> 
> >> I wish I could reliably repeat it.  Given that it occurs after
> >> many hours of work, `emacs -Q` isn't an option.
> 
> Thanks.
> I stared at the code for a bit trying to see how that assertion failure
> can occur, but nothing came to mind yet.  I think we'll need more data.
> 
> Can you try to install the patch below, then run with
> `debug-on-error` enabled?
> Hopefully when the error occurs, this will give us more info (ideally
> including a backtrace).
> 
> 
>         Stefan
> 
> diff --git a/lisp/emacs-lisp/track-changes.el b/lisp/emacs-lisp/track-changes.el
> index 92d14959763..325a92317ca 100644
> --- a/lisp/emacs-lisp/track-changes.el
> +++ b/lisp/emacs-lisp/track-changes.el
> @@ -229,6 +229,7 @@ track-changes-register
>      (push tracker track-changes--clean-trackers)
>      (when disjoint
>        (push tracker track-changes--disjoint-trackers))
> +    (cl-assert (track-changes--sane-state-p))
>      tracker))
>  
>  (defun track-changes-unregister (id)
> @@ -253,7 +254,8 @@ track-changes-unregister
>              track-changes--buffer-size
>              track-changes--before-clean
>              track-changes--state))
> -    (remove-hook 'after-change-functions  #'track-changes--after  t)))
> +    (remove-hook 'after-change-functions  #'track-changes--after  t))
> +  (cl-assert (track-changes--sane-state-p)))
>  
>  (defun track-changes-fetch (id func)
>    "Fetch the pending changes for tracker ID pass them to FUNC.
> @@ -372,7 +374,8 @@ track-changes-fetch
>            (funcall func beg end (or before lenbefore)))
>        ;; Re-enable the tracker's signal only after running `func', so
>        ;; as to avoid nested invocations.
> -      (cl-pushnew id track-changes--clean-trackers))))
> +      (cl-pushnew id track-changes--clean-trackers)
> +      (cl-assert (track-changes--sane-state-p)))))
>  
>  (defun track-changes-inconsistent-state-p ()
>    "Return whether the current buffer is in an inconsistent state.
> @@ -387,6 +390,19 @@ track-changes-inconsistent-state-p
>  
>  ;;;; Auxiliary functions.
>  
> +(defun track-changes--sane-state-p ()
> +  (and (equal track-changes--buffer-size (buffer-size))
> +       (or track-changes--before-no
> +           (pcase track-changes--before-clean
> +             ('unset t)
> +             ('set (<= track-changes--before-beg track-changes--before-end))
> +             ('nil
> +              (<= track-changes--before-beg
> +                  (track-changes--state-beg track-changes--state)
> +                  (track-changes--state-end track-changes--state)
> +                  track-changes--before-end))
> +             (_ nil)))))
> +
>  (defun track-changes--clean-state ()
>    (cond
>     ((null track-changes--state)
> @@ -551,7 +567,8 @@ track-changes--before
>                                       (length track-changes--before-string))))))
>                (setf track-changes--before-end new-bend)
>                (cl-callf concat track-changes--before-string
> -                (buffer-substring-no-properties old-bend new-bend)))))))))
> +                (buffer-substring-no-properties old-bend new-bend))))))))
> +  (cl-assert (track-changes--sane-state-p)))
>  
>  (defun track-changes--after (beg end len)
>    (cl-assert track-changes--state)
> @@ -576,10 +593,26 @@ track-changes--after
>          ;; BEG..END is not covered by previous `before-change-functions'!!
>          (track-changes--recover-from-error `(unexpected-after ,beg ,end ,len))
>        ;; Note the new changes.
> +      (let ((orig-beg (track-changes--state-beg track-changes--state))
> +            (orig-end (track-changes--state-end track-changes--state)))
>        (when (< beg (track-changes--state-beg track-changes--state))
>          (setf (track-changes--state-beg track-changes--state) beg))
>        (cl-callf (lambda (old-end) (max end (+ old-end offset)))
>            (track-changes--state-end track-changes--state))
> +      (cl-assert (or track-changes--before-no
> +                     (<= track-changes--before-beg
> +                         (track-changes--state-beg track-changes--state)))
> +                 nil "<=? %S %S (was %S)"
> +                 track-changes--before-beg
> +                 (track-changes--state-beg track-changes--state)
> +                 orig-beg)
> +      (cl-assert (or track-changes--before-no
> +                     (<= (track-changes--state-end track-changes--state)
> +                         track-changes--before-end))
> +                 nil "<=? %S %S (was %S)"
> +                 (track-changes--state-end track-changes--state)
> +                 track-changes--before-end
> +                 orig-end))
>        (cl-assert (or track-changes--before-no
>                       (<= track-changes--before-beg
>                           (track-changes--state-beg track-changes--state)
> @@ -591,7 +624,8 @@ track-changes--after
>        (if (track-changes--tracker-immediate tracker)
>            (funcall (track-changes--tracker-signal tracker) tracker)
>          (run-with-timer 0 nil #'track-changes--call-signal
> -                        (current-buffer) tracker)))))
> +         (current-buffer) tracker))))
> +  (cl-assert (track-changes--sane-state-p)))
>  
>  (defun track-changes--call-signal (buf tracker)
>    (when (buffer-live-p buf)
> diff --git a/lisp/progmodes/eglot.el b/lisp/progmodes/eglot.el
> index 82e99a2c920..a2c9f73fc73 100644
> --- a/lisp/progmodes/eglot.el
> +++ b/lisp/progmodes/eglot.el
> @@ -2813,6 +2813,8 @@ eglot--signal-textDocument/didChange
>  
>  (defun eglot--signal-textDocument/didOpen ()
>    "Send textDocument/didOpen to server."
> +  ;; Flush any potential pending change.
> +  (eglot--track-changes-fetch eglot--track-changes)
>    (setq eglot--recent-changes nil
>          eglot--versioned-identifier 0
>          eglot--TextDocumentIdentifier-cache nil)