bug#75209: 30.0.93; Emacs reader failed to read data in "/home/nlj/.cache/org-persist/gc-lock.eld"

[N. Jackson]

At 09:02 -0500 on Friday 2025-02-14, N. Jackson wrote:
>
> At 18:01 +0000 on Monday 2025-02-10, Ihor Radchenko wrote:
>>
>> diff --git a/lisp/org-persist.el b/lisp/org-persist.el
>> index a639699d93..58facc0b30 100644
>> --- a/lisp/org-persist.el
>> +++ b/lisp/org-persist.el
>> @@ -449,7 +449,9 @@ (defun org-persist--read-elisp-file (&optional 
>> buffer-or-file)
>>               (message "Emacs reader failed to read data in %S. The error 
>> was: %S"
>>                        buffer-or-file (error-message-string err))
>>             (warn "Emacs reader failed to read data in %S. The error was: %S"
>> -                 buffer-or-file (error-message-string err)))
>> +                 buffer-or-file (error-message-string err))
>> +           (warn "The problematic file contents is:\n-----\n%s\n------\n"
>> +                 (buffer-string)))
>>           nil)))))
>>  
>>  ;; FIXME: `pp' is very slow when writing even moderately large datasets
>
> I have applied your diff and will report back with details when I
> next get the warning.

The bug occurred again this morning (when the system was waking up
from suspend).  The diagnostic information from the new warning was
this:

  ⛔ Warning (emacs): In org-persist--read-elisp-file: The problematic file 
contents is:
  -----
  ;;   -*- mode: lisp-data; -*-
  (((26548 34513 530425 770000) 26551 61114 665219 11000) ((26548 34583 367592 
501000) 26552 26502 142724 470000)
  ------

Unfortunately however, I cannot say with certainty that this was the
"End of file during parsing" error again (but as I have seen no
other error with this bug, I feel fairly sure that it was).


I apologise that I don't have this information.  My elisp is poor
and I am having difficulties with the above patch -- only the first
warning in the else clause gets displayed.

Initially I applied the diff using diff-mode.  It seemed to apply
cleanly.  Then I byte-compiled and loaded, and native-compiled and
loaded the file.  Fairly soon the bug occurred again but the only
warning shown in the *Warnings* buffer was the usual

  ⛔ Warning (emacs): Emacs reader failed to read data in 
"/home/nlj/.cache/org-persist/gc-lock.eld". The error was: "End of file during 
parsing"

.  There was no sign of the output from the new diagnostic.

I convinced myself that the change had applied to the right file and
that Emacs was using the modified code.

I find with Elisp that I have difficulty seeing easily which
statements are inside which block (and I find the asymmetry of the
then part and the else part(s) of if statements especially tricky),
but as far as I could tell the code looked right provided that the
`warn' function is expected to return.

Anyway, to see if poking it would help, I switched the order of the
two warning statements.  I now have this in the error handler in
org-persist--read-elisp-file:

  (error
   ;; Remove problematic file.
   (unless (bufferp buffer-or-file) (delete-file buffer-or-file))
   ;; Do not report the known error to user.
   (if (string-match-p "Invalid read syntax" (error-message-string err))
       (message "Emacs reader failed to read data in %S. The error was: %S"
                buffer-or-file (error-message-string err))
     (warn "In org-persist--read-elisp-file: The problematic file contents 
is:\n-----\n%s\n------\n"
           (buffer-string))
     (warn "In org-persist--read-elisp-file: Emacs reader failed to read data 
in %S. The error was: %S"
           buffer-or-file (error-message-string err)))
   nil)))))

Today was the first time the bug occurred with this version of the
diagnostic and as I reported above, again I only got the output from
the first warning -- which is now the new diagnostic information but
I didn't get the information from the second warning about what the
error was.

I'm not sure what is wrong with this else clause.


With regards to the timing of the triggering of the bug, I have
recently added an :around advice to org-persist--refresh-gc-lock
timer handler to log the exact time and the state of the timer
immediately before the function is entered and immediately after it
exits.  (If it exits.  It doesn't when the bug happens).

When the bug happened this morning, my logs show that my normal
instance of Emacs entered the org-persist--refresh-gc-lock timer
handler at 06:46:07.188999 and never returned, whereas my Gnus
instance of Emacs entered org-persist--refresh-gc-lock eight times
(the number hours of suspend) starting at 06:46:07.295370 and
finishing at 06:46:14.192108.


FWIW, the details from my log (showing the last two invocations of
the timer before I put the system into suspend last night, the
invocations at the time when the system resumed from suspend, and
(in the case of the timer that didn't break), the first regular
invocation of the timer since I woke the system up.)

(I apologise if this is just noise -- I realise that the breaking of
the timer is orthogonal to the problem with the Org persist cache.)

Note: The due time in seconds is nonsense when it is negative
because of the bug in float-time.

Normal Emacs instance (bug happened here):

2025-02-20 21:10:50.625671 Norm entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.989584552 s (26551 61114 615308 958000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-20 21:10:50.630169 Norm leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.985085596 s (26551 61114 615308 958000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-20 22:10:50.622359 Norm entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.992908008 s (26551 64714 615308 958000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-20 22:10:50.666588 Norm leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.948640987 s (26551 64714 615308 958000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:07.188999 Norm entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -23716.573737732 s (26552 2778 615308 958000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil


Gnus Emacs instance:

2025-02-20 21:11:55.035594 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.992966593 s (26551 61179 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-20 21:11:55.063103 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.965491277 s (26551 61179 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-20 22:11:55.043835 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.984760117 s (26551 64779 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-20 22:11:55.058196 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.970393228 s (26551 64779 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:07.295370 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -23652.266766201 s (26552 2843 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.143748 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -23659.115148904 s (26552 2843 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.148166 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -20059.119561876 s (26552 6443 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.179593 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -20059.151004079 s (26552 6443 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.180383 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -16459.151768947 s (26552 10043 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.181836 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -16459.153224063 s (26552 10043 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.182532 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -12859.153917435 s (26552 13643 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.183997 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -12859.155382942 s (26552 13643 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.184627 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -9259.156007449 s (26552 17243 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.186050 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -9259.157438955 s (26552 17243 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.186715 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -5659.158116718 s (26552 20843 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.188074 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -5659.159457743 s (26552 20843 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.188685 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -2059.160065622 s (26552 24443 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.190071 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In -2059.161456207 s (26552 24443 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 06:46:14.190744 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 1540.837851387 s (26552 28043 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 06:46:14.192108 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 1540.836489647 s (26552 28043 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

2025-02-21 07:11:55.051565 Gnus entering org-persist--refresh-gc-lock:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.97701699 s (26552 31643 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil

  2025-02-21 07:11:55.072352 Gnus leaving org-persist--refresh-gc-lock normally:
  Timer: org-persist--refresh-gc-lock (nil)
  Due: In 3599.956240079 s (26552 31643 28641 22000)
  Triggered: t          Integral Multiple: nil
  Repeat Delay: 3600    Idle Delay: nil