#76486 `guix substitute' occasionally crashes while looking for substitutes

Message #5 received at submit@debbugs.gnu.org (full text, mbox, reply):

From: "Timo Wilken" <guix@twilken.net>

To: <bug-guix@gnu.org>

Subject: `guix substitute' occasionally crashes while looking for substitutes

Date: Sat, 22 Feb 2025 16:00:44 +0100

Sometimes, apparently randomly, `guix substitute' crashes as follows for me:

substitute: looking for substitutes on 'https://bordeaux.guix.gnu.org'...   0.0%guix substitute: error: TLS error in procedure 'write_to_session_record_port': Error in the push function.
guix system: error: `/gnu/store/jpbjljfva1hqspw1kd6hgnl63sgvw966-guix-1.4.0-32.5f6fdad/bin/guix substitute' died unexpectedly

This seems to happen while looking for substitutes, usually (always?) at
"0.0%" progress.

This happens rarely enough that a re-run of the crashing "guix system
reconfigure" or "guix home reconfigure" will succeed.

For completeness' sake:

$ guix describe
Generation 114	Feb 21 2025 17:59:33	(current)
  tw 028ba0e
    repository URL: https://git.twilken.net/dotfiles
    branch: master
    commit: 028ba0ea65bc1d2b5a8c59bc336908a161c65e7c
  guix dfabaa8
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: dfabaa8a6faa58612a069eb47ee3f35a94b146fb
  [non-free channels redacted]

Cheers,
Timo

Message #8 received at 76486@debbugs.gnu.org (full text, mbox, reply):

From: 45mg <45mg.writes@gmail.com>

To: Timo Wilken <guix@twilken.net>, 76486@debbugs.gnu.org

Subject: Re: bug#76486: `guix substitute' occasionally crashes while looking for substitutes

Date: Sun, 23 Feb 2025 13:42:16 +0000

Hi Timo,

"Timo Wilken" <guix@twilken.net> writes:

> substitute: looking for substitutes on 'https://bordeaux.guix.gnu.org'...   0.0%guix substitute: error: TLS error in procedure 'write_to_session_record_port': Error in the push function.
> guix system: error: `/gnu/store/jpbjljfva1hqspw1kd6hgnl63sgvw966-guix-1.4.0-32.5f6fdad/bin/guix substitute' died unexpectedly

This issue has been around for a while:
https://yhetil.org/guix/1843db1b-0ed0-7e77-5a31-de8ee9ca56a5@gmail.com/

I and others I know also face it.

Message #15 received at 76486@debbugs.gnu.org (full text, mbox, reply):

From: Ludovic Courtès <ludo@gnu.org>

To: "Timo Wilken" <guix@twilken.net>

Cc: 75679@debbugs.gnu.org, 76486@debbugs.gnu.org, Christopher Baines <guix@cbaines.net>

Subject: Re: bug#76486: `guix substitute' occasionally crashes while looking for substitutes

Date: Tue, 25 Feb 2025 17:04:59 +0100

Hi,

"Timo Wilken" <guix@twilken.net> skribis:

> Sometimes, apparently randomly, `guix substitute' crashes as follows for me:
>
> substitute: looking for substitutes on 'https://bordeaux.guix.gnu.org'...   0.0%guix substitute: error: TLS error in procedure 'write_to_session_record_port': Error in the push function.
> guix system: error: `/gnu/store/jpbjljfva1hqspw1kd6hgnl63sgvw966-guix-1.4.0-32.5f6fdad/bin/guix substitute' died unexpectedly

I’ve sent patch fixing the client-side issue:

  https://issues.guix.gnu.org/76558

Now, I think this only happens with bordeaux.guix.gnu.org, and started
to happen more frequently lately.

Substitutes there are served by nar-herder so I wonder what’s special
about it compared to ‘guix publish’ (used on ci.guix).

Looking at the logs, the nar-herder doesn’t crash (i.e., shepherd never
has to respawn it).  The only thing I see in its own log file that might
be suspicious is this:

--8<---------------cut here---------------start------------->8---
2025-02-23 21:33:00 error: #<procedure 7fba1010cc60 at nar-herder/storage.scm:433:13 ()>:
2025-02-23 21:33:00   #<&port-read-timeout thunk: #<procedure 7fba1010cc80 at nar-herder/storage.scm:431:10 ()> port: #<closed: file 7fb9512eb700>>,
2025-02-23 21:33:00   attempt 1 of 3, retrying in 5
2025-02-23 21:33:01 2025-02-23 21:33:01 (INFO ): processing 1 recent changes
2025-02-23 21:33:11 2025-02-23 21:33:11 (INFO ): processing 1 recent changes
2025-02-23 21:33:21 2025-02-23 21:33:21 (INFO ): processing 1 recent changes
2025-02-23 21:33:31 2025-02-23 21:33:31 (INFO ): processing 1 recent changes
2025-02-23 21:33:35 error: #<procedure 7fba1010cc60 at nar-herder/storage.scm:433:13 ()>:
2025-02-23 21:33:35   #<&port-read-timeout thunk: #<procedure 7fba1010cc80 at nar-herder/storage.scm:431:10 ()> port: #<closed: file 7fb946607070>>,
2025-02-23 21:33:35   attempt 2 of 3, last retry in 5
2025-02-23 21:33:40 running last retry of #<procedure 7fba1010cc60 at nar-herder/storage.scm:433:13 ()> after 2 failed attempts
2025-02-23 21:33:51 2025-02-23 21:33:51 (INFO ): processing 1 recent changes
2025-02-23 21:33:58 error: #<procedure 7fb95e06b640 at nar-herder/storage.scm:433:13 ()>:
2025-02-23 21:33:58   #<&compound-exception components: (#<&error> #<&irritants irritants: (read-header-line #<eof>)> #<&exception-with-kind-and-args kind: bad-header args: (read-header-line #<eof>)>)>,
2025-02-23 21:33:58   attempt 1 of 3, retrying in 5
--8<---------------cut here---------------end--------------->8---

WDYT, Chris?

Thanks,
Ludo’.

Send a report that this bug log contains spam.