GNU bug report logs - #76486
`guix substitute' occasionally crashes while looking for substitutes

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 76486 in the body.
You can then email your comments to 76486 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

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

From: "Timo Wilken" <guix <at> twilken.net>
To: <bug-guix <at> 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 <at> debbugs.gnu.org (full text, mbox):

From: 45mg <45mg.writes <at> gmail.com>
To: Timo Wilken <guix <at> twilken.net>, 76486 <at> 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 <at> 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 <at> gmail.com/

I and others I know also face it.

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: "Timo Wilken" <guix <at> twilken.net>
Cc: 75679 <at> debbugs.gnu.org, 76486 <at> debbugs.gnu.org,
 Christopher Baines <guix <at> 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 <at> 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’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.