Error handling when 'guix substitute' dies

Error handling when 'guix substitute' dies

[Ada Stevenson]

Hi Guix,

I have this gripe with usability regarding using substitutes.

Sometimes, usually when I'm on an enterprise network like my 
university's of library's wifi, the `guix substitute` process dies with 
a "TLS error in procedure 'write_to_session_record_port': Error in the 
push function" error message. My connection is rock-solid otherwise, and 
sometimes it doesn't happen at all.

I'm not sure if this is a fault in the actual Guix code, or there's some 
Guile library somewhere that has this bug. Anyway, I think it would be a 
useful feature to have a way to automatically restart the `guix 
substitute` process or otherwise recover from this error. Some sort of 
`--restart=no.restarts.permitted` flag. Whenever I'm updating my system 
I tend to leave and do something else, and when this happens I come back 
and nothing's actually been done, and the error is transient so I don't 
gain anything from seeing this message.

I workaround could potentially be wrapping `guix upgrade` and the like 
in a script that keeps on restarting the commands until they exit with 
0. This seems a little clunky and fragile, especially if there's an 
actually fatal error, eg. my config is not valid.

What do you guys think? Would this be something that people would be 
interested in? Or would it be better to try and find out why there's 
these transient errors (a way more time-consuming effort, I fear). Does 
anyone else have this issue?

Warmly,

Ada

Re: Error handling when 'guix substitute' dies

[Ekaitz Zarraga]

Hi Ada,

On 2024-03-17 07:18, Ada Stevenson wrote:
> Hi Guix,
> 
> I have this gripe with usability regarding using substitutes.
> 
> Sometimes, usually when I'm on an enterprise network like my 
> university's of library's wifi, the `guix substitute` process dies with 
> a "TLS error in procedure 'write_to_session_record_port': Error in the 
> push function" error message. My connection is rock-solid otherwise, and 
> sometimes it doesn't happen at all.
> 
> I'm not sure if this is a fault in the actual Guix code, or there's some 
> Guile library somewhere that has this bug. Anyway, I think it would be a 
> useful feature to have a way to automatically restart the `guix 
> substitute` process or otherwise recover from this error. Some sort of 
> `--restart=no.restarts.permitted` flag. Whenever I'm updating my system 
> I tend to leave and do something else, and when this happens I come back 
> and nothing's actually been done, and the error is transient so I don't 
> gain anything from seeing this message.
> 
> I workaround could potentially be wrapping `guix upgrade` and the like 
> in a script that keeps on restarting the commands until they exit with 
> 0. This seems a little clunky and fragile, especially if there's an 
> actually fatal error, eg. my config is not valid.
> 
> What do you guys think? Would this be something that people would be 
> interested in? Or would it be better to try and find out why there's 
> these transient errors (a way more time-consuming effort, I fear). Does 
> anyone else have this issue?
> 
> Warmly,
> 
> Ada

Yes. I do have this error in the most inconvenient moments.
This is, if I'm not mistaken, a connection error. It has been randomly 
happening for long time (months?).

We should do something about this, probably handling the case a little 
bit better to at least give the user useful information about what 
happened to be wrong. Or take a look to the substitute servers, I think 
they are the problem, more than the users' guix code.

Rerunning things, sometimes several times, finally happens to work, but 
yes, this is very annoying.

Cheers,
Ekaitz

Re: Error handling when 'guix substitute' dies

[Ludovic Courtès]

[-- Attachment #1: Type: text/plain, Size: 1458 bytes --]

Hi Ada,

Ada Stevenson <adanskana@gmail.com> skribis:

> Sometimes, usually when I'm on an enterprise network like my
> university's of library's wifi, the `guix substitute` process dies
> with a "TLS error in procedure 'write_to_session_record_port': Error
> in the push function" error message. My connection is rock-solid
> otherwise, and sometimes it doesn't happen at all.

What version of guix-daemon are you using?  Was it installed through
‘guix pull’ or via another distro?

I’ve seen this before but I haven’t experienced it in a long time, so I
wonder if I’m just lucky or if there are other factors at play.

> I'm not sure if this is a fault in the actual Guix code, or there's
> some Guile library somewhere that has this bug. Anyway, I think it
> would be a useful feature to have a way to automatically restart the
> `guix substitute` process or otherwise recover from this error. Some
> sort of `--restart=no.restarts.permitted` flag. Whenever I'm updating
> my system I tend to leave and do something else, and when this happens
> I come back and nothing's actually been done, and the error is
> transient so I don't gain anything from seeing this message.

‘guix substitute’ is a ‘guix-daemon’ helper, which automatically
(re)starts it when needed.

Now, what we could do is have ‘guix substitute’ gracefully handle those
errors and keep going.  I believe this one-liner should do it:


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 693 bytes --]

diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
index 37cd08e289..3af0bf0019 100755
--- a/guix/scripts/substitute.scm
+++ b/guix/scripts/substitute.scm
@@ -494,7 +494,9 @@ (define* (download-nar narinfo destination
   (define (try-fetch choices)
     (match choices
       (((uri compression file-size) rest ...)
-       (guard (c ((and (pair? rest) (http-get-error? c))
+       (guard (c ((and (pair? rest)
+                       (or (http-get-error? c)
+                           (network-error? c)))
                   (warning (G_ "download from '~a' failed, trying next URL~%")
                            (uri->string uri))
                   (try-fetch rest)))

[-- Attachment #3: Type: text/plain, Size: 85 bytes --]


I’ll go ahead with this change if there are no objections.

Thanks,
Ludo’.

Re: Error handling when 'guix substitute' dies

[Ada Stevenson]

Hi Ludo',

On 3/24/24 11:15 AM, Ludovic Courtès wrote:
> Hi Ada,
>
> Ada Stevenson <adanskana@gmail.com> skribis:
>
>> Sometimes, usually when I'm on an enterprise network like my
>> university's of library's wifi, the `guix substitute` process dies
>> with a "TLS error in procedure 'write_to_session_record_port': Error
>> in the push function" error message. My connection is rock-solid
>> otherwise, and sometimes it doesn't happen at all.
> What version of guix-daemon are you using?  Was it installed through
> ‘guix pull’ or via another distro?
>
> I’ve seen this before but I haven’t experienced it in a long time, so I
> wonder if I’m just lucky or if there are other factors at play.
I'm running the up-to-date daemon, 1.4.0-18.4c94b9e, on Guix System.
>
>> I'm not sure if this is a fault in the actual Guix code, or there's
>> some Guile library somewhere that has this bug. Anyway, I think it
>> would be a useful feature to have a way to automatically restart the
>> `guix substitute` process or otherwise recover from this error. Some
>> sort of `--restart=no.restarts.permitted` flag. Whenever I'm updating
>> my system I tend to leave and do something else, and when this happens
>> I come back and nothing's actually been done, and the error is
>> transient so I don't gain anything from seeing this message.
> ‘guix substitute’ is a ‘guix-daemon’ helper, which automatically
> (re)starts it when needed.
>
> Now, what we could do is have ‘guix substitute’ gracefully handle those
> errors and keep going.  I believe this one-liner should do it:
>
>
> diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
> index 37cd08e289..3af0bf0019 100755
> --- a/guix/scripts/substitute.scm
> +++ b/guix/scripts/substitute.scm
> @@ -494,7 +494,9 @@ (define* (download-nar narinfo destination
>     (define (try-fetch choices)
>       (match choices
>         (((uri compression file-size) rest ...)
> -       (guard (c ((and (pair? rest) (http-get-error? c))
> +       (guard (c ((and (pair? rest)
> +                       (or (http-get-error? c)
> +                           (network-error? c)))
>                     (warning (G_ "download from '~a' failed, trying next URL~%")
>                              (uri->string uri))
>                     (try-fetch rest)))
>
> I’ll go ahead with this change if there are no objections.
Looks good to me! Thanks for looking into this :)
>
> Thanks,
> Ludo’.

Thanks,

Ada

Re: Error handling when 'guix substitute' dies

[Lars Bilke]

[-- Attachment #1: Type: text/plain, Size: 444 bytes --]

Dear Ada and Ludo,

thanks Ada for bringing this issue up again. I get the same error on 
`guix pull` almost always when I am on my enterprise network. Re-running 
`guix pull` a second time also almost always then runs fine. I checked 
with our IT: nothing suspicious on the network, i.e. no firewall 
blocking.

I never experienced the error on my home network.

Ludo, it would just awesome if your fix resolves the issue!

Thanks a lot,
Lars

[-- Attachment #2: Type: text/html, Size: 961 bytes --]

Re: Error handling when 'guix substitute' dies

[Ludovic Courtès]

Hello,

Ada Stevenson <adanskana@gmail.com> skribis:

>> diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
>> index 37cd08e289..3af0bf0019 100755
>> --- a/guix/scripts/substitute.scm
>> +++ b/guix/scripts/substitute.scm
>> @@ -494,7 +494,9 @@ (define* (download-nar narinfo destination
>>     (define (try-fetch choices)
>>       (match choices
>>         (((uri compression file-size) rest ...)
>> -       (guard (c ((and (pair? rest) (http-get-error? c))
>> +       (guard (c ((and (pair? rest)
>> +                       (or (http-get-error? c)
>> +                           (network-error? c)))
>>                     (warning (G_ "download from '~a' failed, trying next URL~%")
>>                              (uri->string uri))
>>                     (try-fetch rest)))
>>
>> I’ll go ahead with this change if there are no objections.
> Looks good to me! Thanks for looking into this :)

OK, I’ll push it shortly, but…

Lars Bilke <lars.bilke@ufz.de> skribis:

> thanks Ada for bringing this issue up again. I get the same error on
> `guix pull` almost always when I am on my enterprise
> network. Re-running `guix pull` a second time also almost always then
> runs fine. I checked with our IT: nothing suspicious on the network,
> i.e. no firewall blocking.
>
> I never experienced the error on my home network.

… your reports make me think there’s a bug lurking somewhere that
perhaps only manifests under some precise networking or timing
conditions.

Could the two of you run the following command in a loop to see whether
it’s easy to reproduce that GnuTLS error?

  guile -c '(use-modules (guix http-client) (ice-9 binary-ports))
    (get-bytevector-all (http-fetch "https://ci.guix.gnu.org/nix-cache-info"))'

If you can reproduce it, could you capture the strace output of the
process?  You would run the command above prefixed by:

  strace -o log.strace -s 300 …

Thanks in advance!

Ludo’.

Re: Error handling when 'guix substitute' dies

[Philip McGrath]

Hi,

On 3/29/24 11:10, Ludovic Courtès wrote:
 >
 > [...]
> 
> OK, I’ll push it shortly, but…
> 
> Lars Bilke <lars.bilke@ufz.de> skribis:
> 
>> thanks Ada for bringing this issue up again. I get the same error on
>> `guix pull` almost always when I am on my enterprise
>> network. Re-running `guix pull` a second time also almost always then
>> runs fine. I checked with our IT: nothing suspicious on the network,
>> i.e. no firewall blocking.
>>
>> I never experienced the error on my home network.
> 
> … your reports make me think there’s a bug lurking somewhere that
> perhaps only manifests under some precise networking or timing
> conditions.
> 
> Could the two of you run the following command in a loop to see whether
> it’s easy to reproduce that GnuTLS error?
> 
>    guile -c '(use-modules (guix http-client) (ice-9 binary-ports))
>      (get-bytevector-all (http-fetch "https://ci.guix.gnu.org/nix-cache-info"))'
> 
> If you can reproduce it, could you capture the strace output of the
> process?  You would run the command above prefixed by:
> 
>    strace -o log.strace -s 300 …
> 

I don't know if the root cause is related, but this reminded me of some 
networking errors I sometimes get accessing substitutes. I had the luck 
(good or bad?) to get an example while building 
<https://issues.guix.gnu.org/70065>, so I thought I'd report.

> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
> ERROR:
>   1. &http-get-error:
>       uri: #<<uri> scheme: https userinfo: #f host: "bordeaux-us-east-mirror.cbaines.net" port: #f path: "/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz" query: #f fragment: #f>
>       code: 404
>       reason: "Not Found"
>       headers: ((server . "nginx") (date . #<date nanosecond: 0 second: 9 minute: 20 hour: 6 day: 1 month: 4 year: 2024 zone-offset: 0>) (content-type application/json (charset . "utf-8")) (content-length . 35) (connection keep-alive))
>   2. &message: "https://bordeaux-us-east-mirror.cbaines.net/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz: HTTP download failed: 404 (\"Not Found\")"
> substitution of /gnu/store/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz failed
> guix build: error: corrupt input while restoring archive from #<closed: file 7f9f7deaad90>

The last time this happened, I kept rerunning the command a bunch of 
times. When it succeeded with the first substitute with the problem, it 
hit the problem with another substitute, for several rounds, but 
eventually the whole thing succeeded.

In this incident, the command failed a few times, so I ran:

     guix build --no-substitutes --source chez-fmt

and then ran my original command again, successfully.

Hope this is useful,
Philip

Re: Error handling when 'guix substitute' dies

[Lars Bilke]

Dear Ludo,

I ran the command in a loop on 4 machines for around 2 hours doing 1 request per machine per second but no errors occured...

On 29 Mar 2024, at 16:10, Ludovic Courtès wrote:

> Hello,
>
> Ada Stevenson <adanskana@gmail.com> skribis:
>
>>> diff --git a/guix/scripts/substitute.scm b/guix/scripts/substitute.scm
>>> index 37cd08e289..3af0bf0019 100755
>>> --- a/guix/scripts/substitute.scm
>>> +++ b/guix/scripts/substitute.scm
>>> @@ -494,7 +494,9 @@ (define* (download-nar narinfo destination
>>>     (define (try-fetch choices)
>>>       (match choices
>>>         (((uri compression file-size) rest ...)
>>> -       (guard (c ((and (pair? rest) (http-get-error? c))
>>> +       (guard (c ((and (pair? rest)
>>> +                       (or (http-get-error? c)
>>> +                           (network-error? c)))
>>>                     (warning (G_ "download from '~a' failed, trying next URL~%")
>>>                              (uri->string uri))
>>>                     (try-fetch rest)))
>>>
>>> I’ll go ahead with this change if there are no objections.
>> Looks good to me! Thanks for looking into this :)
>
> OK, I’ll push it shortly, but…
>
> Lars Bilke <lars.bilke@ufz.de> skribis:
>
>> thanks Ada for bringing this issue up again. I get the same error on
>> `guix pull` almost always when I am on my enterprise
>> network. Re-running `guix pull` a second time also almost always then
>> runs fine. I checked with our IT: nothing suspicious on the network,
>> i.e. no firewall blocking.
>>
>> I never experienced the error on my home network.
>
> … your reports make me think there’s a bug lurking somewhere that
> perhaps only manifests under some precise networking or timing
> conditions.
>
> Could the two of you run the following command in a loop to see whether
> it’s easy to reproduce that GnuTLS error?
>
>   guile -c '(use-modules (guix http-client) (ice-9 binary-ports))
>     (get-bytevector-all (http-fetch "https://ci.guix.gnu.org/nix-cache-info"))'
>
> If you can reproduce it, could you capture the strace output of the
> process?  You would run the command above prefixed by:
>
>   strace -o log.strace -s 300 …
>
> Thanks in advance!
>
> Ludo’.

Re: Error handling when 'guix substitute' dies

[Ada Stevenson]

[-- Attachment #1: Type: text/plain, Size: 2882 bytes --]

Hi Lars,

On Tue, Apr 2 2024 at 10:42:18 AM +0200, Lars Bilke <lars.bilke@ufz.de> 
wrote:
> Dear Ludo,
> 
> I ran the command in a loop on 4 machines for around 2 hours doing 1 
> request per machine per second but no errors occured...
I did a similar thing. No errors at all.
However, I was reconfiguring my system at uni yesterday after the 
gnome-team merge and it was happening a lot! I wonder if it's something 
to do with the server? I don't know enough about networking to really 
theorise, haha.
> 
> On 29 Mar 2024, at 16:10, Ludovic Courtès wrote:
> 
>>  Hello,
>> 
>>  Ada Stevenson <adanskana@gmail.com <mailto:adanskana@gmail.com>> 
>> skribis:
>> 
>>>>  diff --git a/guix/scripts/substitute.scm 
>>>> b/guix/scripts/substitute.scm
>>>>  index 37cd08e289..3af0bf0019 100755
>>>>  --- a/guix/scripts/substitute.scm
>>>>  +++ b/guix/scripts/substitute.scm
>>>>  @@ -494,7 +494,9 @@ (define* (download-nar narinfo destination
>>>>      (define (try-fetch choices)
>>>>        (match choices
>>>>          (((uri compression file-size) rest ...)
>>>>  -       (guard (c ((and (pair? rest) (http-get-error? c))
>>>>  +       (guard (c ((and (pair? rest)
>>>>  +                       (or (http-get-error? c)
>>>>  +                           (network-error? c)))
>>>>                      (warning (G_ "download from '~a' failed, 
>>>> trying next URL~%")
>>>>                               (uri->string uri))
>>>>                      (try-fetch rest)))
>>>> 
>>>>  I’ll go ahead with this change if there are no objections.
>>>  Looks good to me! Thanks for looking into this :)
>> 
>>  OK, I’ll push it shortly, but…
>> 
>>  Lars Bilke <lars.bilke@ufz.de <mailto:lars.bilke@ufz.de>> skribis:
>> 
>>>  thanks Ada for bringing this issue up again. I get the same error 
>>> on
>>>  `guix pull` almost always when I am on my enterprise
>>>  network. Re-running `guix pull` a second time also almost always 
>>> then
>>>  runs fine. I checked with our IT: nothing suspicious on the 
>>> network,
>>>  i.e. no firewall blocking.
>>> 
>>>  I never experienced the error on my home network.
>> 
>>  … your reports make me think there’s a bug lurking somewhere 
>> that
>>  perhaps only manifests under some precise networking or timing
>>  conditions.
>> 
>>  Could the two of you run the following command in a loop to see 
>> whether
>>  it’s easy to reproduce that GnuTLS error?
>> 
>>    guile -c '(use-modules (guix http-client) (ice-9 binary-ports))
>>      (get-bytevector-all (http-fetch 
>> "<https://ci.guix.gnu.org/nix-cache-info>"))'
>> 
>>  If you can reproduce it, could you capture the strace output of the
>>  process?  You would run the command above prefixed by:
>> 
>>    strace -o log.strace -s 300 …
>> 
>>  Thanks in advance!
>> 
>>  Ludo’.
> 
Thanks,
Ada


[-- Attachment #2: Type: text/html, Size: 3359 bytes --]

Re: Error handling when 'guix substitute' dies

[Ludovic Courtès]

Hi,

Philip McGrath <philip@philipmcgrath.com> skribis:

> I don't know if the root cause is related, but this reminded me of
> some networking errors I sometimes get accessing substitutes. I had
> the luck (good or bad?) to get an example while building
> <https://issues.guix.gnu.org/70065>, so I thought I'd report.
>
>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>> ERROR:
>>   1. &http-get-error:
>>       uri: #<<uri> scheme: https userinfo: #f host: "bordeaux-us-east-mirror.cbaines.net" port: #f path: "/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz" query: #f fragment: #f>
>>       code: 404
>>       reason: "Not Found"
>>       headers: ((server . "nginx") (date . #<date nanosecond: 0 second: 9 minute: 20 hour: 6 day: 1 month: 4 year: 2024 zone-offset: 0>) (content-type application/json (charset . "utf-8")) (content-length . 35) (connection keep-alive))
>>   2. &message: "https://bordeaux-us-east-mirror.cbaines.net/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz: HTTP download failed: 404 (\"Not Found\")"
>> substitution of /gnu/store/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz failed
>> guix build: error: corrupt input while restoring archive from #<closed: file 7f9f7deaad90>

No, that’s another problem: bordeaux.guix would delete nars before their
advertised TTL has expired.  See <https://issues.guix.gnu.org/63634#4>.
Chris explained that this was solved recently I believe.

Ludo’.

Re: Error handling when 'guix substitute' dies

[Ludovic Courtès]

Hi,

Lars Bilke <lars.bilke@ufz.de> skribis:

> I ran the command in a loop on 4 machines for around 2 hours doing 1 request per machine per second but no errors occured...

Hmm OK, thanks for testing.  Not sure how to understand the problem
then.  It could be triggered keep-alive and connection reuse, who knows.

If/when that happens again, could you please try to gather as much data
as possible about networking conditions?

Thanks,
Ludo’.

Re: Error handling when 'guix substitute' dies

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 1716 bytes --]

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

> Hi,
>
> Philip McGrath <philip@philipmcgrath.com> skribis:
>
>> I don't know if the root cause is related, but this reminded me of
>> some networking errors I sometimes get accessing substitutes. I had
>> the luck (good or bad?) to get an example while building
>> <https://issues.guix.gnu.org/70065>, so I thought I'd report.
>>
>>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>>> ERROR:
>>>   1. &http-get-error:
>>>       uri: #<<uri> scheme: https userinfo: #f host: "bordeaux-us-east-mirror.cbaines.net" port: #f path: "/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz" query: #f fragment: #f>
>>>       code: 404
>>>       reason: "Not Found"
>>>       headers: ((server . "nginx") (date . #<date nanosecond: 0 second: 9 minute: 20 hour: 6 day: 1 month: 4 year: 2024 zone-offset: 0>) (content-type application/json (charset . "utf-8")) (content-length . 35) (connection keep-alive))
>>>   2. &message: "https://bordeaux-us-east-mirror.cbaines.net/nar/lzip/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz: HTTP download failed: 404 (\"Not Found\")"
>>> substitution of /gnu/store/r8w68mhsvqlkvazncvfn36jcpvz404x6-chez-fmt-0.8.11.tar.gz failed
>>> guix build: error: corrupt input while restoring archive from #<closed: file 7f9f7deaad90>
>
> No, that’s another problem: bordeaux.guix would delete nars before their
> advertised TTL has expired.  See <https://issues.guix.gnu.org/63634#4>.
> Chris explained that this was solved recently I believe.

This only applied to zstd nars, whereas this is an lzip nar that was
apparently missing at the time.

Maybe this is/was some problem with the mirror.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]