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

From: Ihor Radchenko <[email-masked]>
Date: Sun, 23 Feb 2025 18:26:52 +0000

"N. Jackson" <[email-masked]> writes:

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

First of all, thanks a lot of the detailed investigation!

>   ⛔ 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).

That was it. I can see it from unclosed parenthesis.

> 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.

"Else" part may contain any number of sexps, while "then" part only one.
That's why asymmetry.

> 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 am also clueless why only a single warning is shown though.

> 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.

Ouch! It is actually expected (and customizable via
`timer-max-repeats'), but was not intended by me in the code logic.
It does not explain your bug though.

> 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.)

Very helpful!

> Normal Emacs instance (bug happened here):
> ...
> 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

Never returned likely means that it threw an error.
Most likely because

(setf (alist-get before-init-time alist nil nil #'equal)
            (current-time))
will fail when ALIST is nil. I should fix this.
However, it does not solve the mistery of incomplete data in the
lockfile.

> Gnus Emacs instance:
>
> 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

This looks like the most recent write to the lock file.

The one at 6am happens after the failing read at 06:46:07.188999.

On the other hand, it is just a fraction of second apart.
Is `insert-file-contents' atomic operation?

> 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

-- 
Ihor Radchenko // yantar92,
Org mode maintainer,
Learn more about Org mode at <https://orgmode.org/>.
Support Org development at <https://liberapay.com/org-mode>,
or support my work at <https://liberapay.com/yantar92>