#75679 Frequent TLS error in `guix substitute'

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

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

To: <bug-guix@gnu.org>

Subject: Frequent TLS error in `guix substitute'

Date: Sun, 19 Jan 2025 23:57:05 +0100

Hi, unfortunately I frequently get the following error when Guix is looking
for substitutes:

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.

(Formatting as in the original error message - all in one long line.)

This happens during `guix system reconfigure' and `guix home reconfigure', my
most frequently used Guix subcommands.

Re-running the same command usually works, since the error only happens
intermittently. It's not a show-stopper, but still annoying - especially when
I start a long-running Guix command and come back to it later with very little
progress made due to this crash.

This has been happening for a long time (at least a few months), but for
completeness, here is my current `guix describe' output:

Generation 11	Jan 19 2025 23:31:14	(current)
  tw 387cd9f
    repository URL: https://git.twilken.net/dotfiles
    branch: master
    commit: 387cd9f2085d0ef3e192523113b9ed6d9041aae0
  guix 5e834c2
    repository URL: https://git.savannah.gnu.org/git/guix.git
    branch: master
    commit: 5e834c220e81fddb77a26e23cf0cd5055b866844
  [non-free channels omitted]

Message #12 received at 75679@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’.

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

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

To: <75679@debbugs.gnu.org>, <ludo@gnu.org>

Subject: Frequent TLS error in `guix substitute'

Date: Fri, 07 Mar 2025 10:24:56 +0100

Hi Ludo’,

Thank you very much for your effort in tracking this down!

Just to be clear, in case this is server-related: I reported this issue when
it happened to me with bordeaux, but I have a (nonfree) substitute server
before it in the list, which fails more frequently (and which I'm happy to
name on request).

I can't remember ever seeing the same failure with ci.guix.gnu.org, but that
may just be down to random chance, since ci.guix is checked last on my system.

So, my list of substitute servers is, in order:

1. https://substitutes.[redacted].org: most frequent TLS errors
2. https://bordeaux.guix.gnu.org: very occasional TLS errors
3. https://ci.guix.gnu.org: no TLS errors observed

Ludovic Courtès wrote 1 weeks ago <https://issues.guix.gnu.org/76558>:
> At long last. Note that we'll need to update the ‘guix’ package to make this
> change effective.

That explains why it's still happening to me then!

Cheers,
Timo

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

From: Andreas Enge <andreas@enge.fr>

To: Timo Wilken <guix@twilken.net>

Cc: 75679@debbugs.gnu.org, ludo@gnu.org

Subject: Re: Frequent TLS error in `guix substitute'

Date: Tue, 8 Apr 2025 22:31:54 +0200

Hello,

can this be closed now as
   https://issues.guix.gnu.org/76558
is merged?

Andreas

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

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

To: "Andreas Enge" <andreas@enge.fr>

Cc: 75679@debbugs.gnu.org, ludo@gnu.org

Subject: Re: Frequent TLS error in `guix substitute'

Date: Tue, 08 Apr 2025 22:36:06 +0200

Hi Andreas,

On Tue 8 Apr 2025 at 10:31 pm CEST, Andreas Enge wrote:
> can this be closed now as
>    https://issues.guix.gnu.org/76558
> is merged?

I am no longer inconvenienced by this, though I still see the warnings emitted
by the change in the patch you linked, so the underlying issue is still there.

Up to you if you consider this fixed. Feel free to close this if so :)

Cheers,
Timo

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

From: Andreas Enge <andreas@enge.fr>

To: Timo Wilken <guix@twilken.net>

Cc: 75679@debbugs.gnu.org, ludo@gnu.org

Subject: Re: Frequent TLS error in `guix substitute'

Date: Wed, 9 Apr 2025 09:50:16 +0200

Hello Timo,

Am Tue, Apr 08, 2025 at 10:36:06PM +0200 schrieb Timo Wilken:
> I am no longer inconvenienced by this, though I still see the warnings emitted
> by the change in the patch you linked, so the underlying issue is still there.
> Up to you if you consider this fixed. Feel free to close this if so :)

I will let Ludovic decide, I just asked the question since I randomly
stumbled upon this issue.

Andreas

Send a report that this bug log contains spam.