#56005 "write_wait_fd: unimplemented" error from 'guix substitute'

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

From: Thiago Jung Bauermann <bauermann@kolabnow.com>

To: bug-guix@gnu.org

Subject: exception while downloading substitutes

Date: Wed, 15 Jun 2022 23:40:53 -0300

Hello,

I just ran “guix pull && guix package -u” and after downloading many
substitutes, guix package aborted with the following error:

--8<---------------cut here---------------start------------->8---
    ⋮
substitute: atualizando substitutos de "https://ci.guix.gnu.org"...   0.0%Backtrace:
substitute:           14 (primitive-load "/gnu/store/yxh9kr0150494jf8phrf1x28mhw…")
substitute: In guix/ui.scm:
substitute:    2230:7 13 (run-guix . _)
substitute:   2193:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7f22cf4534a0 …> …)
substitute:    322:31  6 (lookup-narinfos "https://ci.guix.gnu.org" _ # _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&error> #<&orig…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute:
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: In procedure write_wait_fd: unimplemented
guix package: erro: `/gnu/store/yxh9kr0150494jf8phrf1x28mhwnnv7f-guix-command substitute' died unexpectedly
popigai: (1) guix describe
Geração 144     15 jun 2022 22:55:58    (atual)
  guix 128697d
    URL do repositório: https://git.savannah.gnu.org/git/guix.git
    ramo: master
    commit: 128697d43c21eb229ff5413f1c4cf79ae1a9dcd4
--8<---------------cut here---------------end--------------->8---

I immediately ran “guix package -u” again, and this time the command
completed successfully.

I had a quick look at ‘fetch-narinfos’ but I couldn't figure out what
could be calling into this unimplemented function ‘write_wait_fd’…

-- 
Thanks
Thiago

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

From: Maxime Devos <maximedevos@telenet.be>

To: Thiago Jung Bauermann <bauermann@kolabnow.com>, 56005@debbugs.gnu.org

Cc: control@debbugs.gnu.org

Subject: Re: bug#56005: "write_wait_fd: unimplemented" during downloading substitutes

Date: Thu, 16 Jun 2022 09:58:24 +0200

[Message part 1 (text/plain, inline)]

retitle 56006 "write_wait_fd: unimplemented" during downloading substitutes
thanks

Thiago Jung Bauermann via Bug reports for GNU Guix schreef op wo 15-06-
2022 om 23:40 [-0300]:
> I had a quick look at ‘fetch-narinfos’ but I couldn't figure out what
> could be calling into this unimplemented function ‘write_wait_fd’…

Untested hypothesis: maybe writing to the TLS-wrapped port constructed
in (guix build download) blocked, so Guile's port code ran
'write_wait_fd', which was not set for the TLS port (in the GnuTLS
library)?  Alternatively: maybe 'make-custom-binary-input/output-port'
in (guix build download) was used incorrectly?

Greetings,
Maxime.

[signature.asc (application/pgp-signature, inline)]

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

From: Attila Lendvai <attila@lendvai.name>

To: "56005@debbugs.gnu.org" <56005@debbugs.gnu.org>

Subject: In procedure write_wait_fd: unimplemented

Date: Thu, 30 Jun 2022 11:48:56 +0000

i'm also seeing this every once in a while.

some speculation: my router has QoS set up that limits the upstream, so that i avoid triggering my ISP's rate limiter, because it sends ping into the ballpark of seconds.

maybe because of this config i'm seeing this more regularly than others?

- attila

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

From: Maxime Devos <maximedevos@telenet.be>

To: 56005@debbugs.gnu.org

Subject: Re: during substitution: write_wait_fd: unimplemented

Date: Thu, 30 Jun 2022 13:51:56 +0200

[Message part 1 (text/plain, inline)]

> substitute:    348:26  8 (process-query #<output: file 4> _ #:cache
urls _ #:acl _)
> substitute: In guix/substitutes.scm:
> substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure
7f22cf4534a0 …> …)
> substitute:    322:31  6 (lookup-narinfos "https://ci.guix.gnu.org" _
# _ # _)
> substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)

For extra debugging information, you could try adding "COLUMNS=999999" to
the environment variables with which the guix daemon is started (where
exactly, depends on the init system).

Greetings,
Maxime.

[signature.asc (application/pgp-signature, inline)]

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

From: Maxime Devos <maximedevos@telenet.be>

To: 56005@debbugs.gnu.org

Subject: Re: during substitution: write_wait_fd: unimplemented

Date: Thu, 30 Jun 2022 13:55:50 +0200

[Message part 1 (text/plain, inline)]

Maxime Devos schreef op do 30-06-2022 om 13:51 [+0200]:
> > substitute:    348:26  8 (process-query #<output: file 4> _ #:cache
> urls _ #:acl _)
> > substitute: In guix/substitutes.scm:
> > substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure
> 7f22cf4534a0 …> …)
> > substitute:    322:31  6 (lookup-narinfos "https://ci.guix.gnu.org"
> > _
> # _ # _)
> > substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ #

This is at  the following ...

substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-
urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure
7f22cf4534a0 …> …)
substitute:    322:31  6 (lookup-narinfos "https://ci.guix.gnu.org" _ #
_ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)

line.  Looks like the error wasn't actually handled.  The reason that
the backtrace was truncated, is that 'catch' was used instead of
'with-exception-handler' + #:unwind? #true.  So to investigate the
error, it might be good to adjust 'call-with-connection-error-handling'
first.

Greetings,
Maxime.

[signature.asc (application/pgp-signature, inline)]

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

From: Maxime Devos <maximedevos@telenet.be>

To: 56005@debbugs.gnu.org

Subject: Re: during substitution: write_wait_fd: unimplemented

Date: Thu, 30 Jun 2022 13:56:35 +0200

[Message part 1 (text/plain, inline)]

Maxime Devos schreef op do 30-06-2022 om 13:55 [+0200]:
> 
> the backtrace was truncated, is that 'catch' was used instead of
> 'with-exception-handler' + #:unwind? #true

Correction: #:unwind? #false.

[signature.asc (application/pgp-signature, inline)]

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

From: Thiago Jung Bauermann <bauermann@kolabnow.com>

To: Maxime Devos <maximedevos@telenet.be>

Cc: 56005@debbugs.gnu.org

Subject: Re: bug#56005: during substitution: write_wait_fd: unimplemented

Date: Sat, 16 Jul 2022 00:34:56 -0300

Hello,

This bug was closed, but I couldn't find what was the resolution of the
problem. Could someone please clarify, for my own education and also so
that it gets documented in the bug report?

-- 
Thanks
Thiago

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

From: Maxime Devos <maximedevos@telenet.be>

To: Thiago Jung Bauermann <bauermann@kolabnow.com>

Cc: 56005@debbugs.gnu.org, control@debbugs.gnu.org

Subject: Re: bug#56005: during substitution: write_wait_fd: unimplemented

Date: Tue, 19 Jul 2022 21:50:19 +0200

[Message part 1 (text/plain, inline)]

reopen 56005
thanks

(not sure if this works because I haven't set up plain-text instead of 
HTML yet ...)


On 16-07-2022 05:34, Thiago Jung Bauermann wrote:

> Hello,
>
> This bug was closed, but I couldn't find what was the resolution of the
> problem. Could someone please clarify, for my own education and also so
> that it gets documented in the bug report?

No reason was given at all for closing (normally it says "solved in 
commit ..." or "cannot reproduce" or such ...) , so I'd assume that the 
wrong bug number was targetted? Tentatively reopening ...

Greetings,
Maxime.

[OpenPGP_0x49E3EE22191725EE.asc (application/pgp-keys, attachment)]

[OpenPGP_signature (application/pgp-signature, attachment)]

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

From: Thiago Jung Bauermann <bauermann@kolabnow.com>

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

Cc: 56005@debbugs.gnu.org, 56867@debbugs.gnu.org, guile-devel@gnu.org

Subject: Re: [bug#56867] [PATCH] download: Do not wrap TLS port on GnuTLS >= 3.7.7.

Date: Thu, 04 Aug 2022 11:46:47 -0300

Hello Ludo,

I don't have any comment/insight on what you're doing in general, except
about one of your points below:

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

> First, I noticed that GnuTLS doesn’t implement ‘write_wait_fd’, only
> ‘read_wait_fd’ (not sure how problematic that is):
>
> scheme@(guile-user)> ,use(web client)
> scheme@(guile-user)> (define p (open-socket-for-uri "https://guix.gnu.org"))
> scheme@(guile-user)> ((@@ (ice-9 suspendable-ports) wait-for-writable) p)
> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
> In procedure write_wait_fd: unimplemented
>
> Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
> scheme@(guile-user) [1]> ,q
> scheme@(guile-user)> ,use(gnutls)
> scheme@(guile-user)> (gnutls-version)
> $1 = "3.7.7"
> scheme@(guile-user)> ((@@ (ice-9 suspendable-ports) wait-for-readable) p)
> $2 = 1

This occasionally causes problems when fetching substitutes, as can be
seen in bug #56005 (during substitution: write_wait_fd: unimplemented).

-- 
Thanks
Thiago

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

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

To: Thiago Jung Bauermann <bauermann@kolabnow.com>

Cc: 56005@debbugs.gnu.org, 56867@debbugs.gnu.org, guile-devel@gnu.org

Subject: Re: [bug#56867] [PATCH] download: Do not wrap TLS port on GnuTLS >= 3.7.7.

Date: Thu, 04 Aug 2022 18:19:37 +0200

Hi,

Thiago Jung Bauermann <bauermann@kolabnow.com> skribis:

> Ludovic Courtès <ludo@gnu.org> writes:
>
>> First, I noticed that GnuTLS doesn’t implement ‘write_wait_fd’, only
>> ‘read_wait_fd’ (not sure how problematic that is):
>>
>> scheme@(guile-user)> ,use(web client)
>> scheme@(guile-user)> (define p (open-socket-for-uri "https://guix.gnu.org"))
>> scheme@(guile-user)> ((@@ (ice-9 suspendable-ports) wait-for-writable) p)
>> ice-9/boot-9.scm:1685:16: In procedure raise-exception:
>> In procedure write_wait_fd: unimplemented
>>
>> Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
>> scheme@(guile-user) [1]> ,q
>> scheme@(guile-user)> ,use(gnutls)
>> scheme@(guile-user)> (gnutls-version)
>> $1 = "3.7.7"
>> scheme@(guile-user)> ((@@ (ice-9 suspendable-ports) wait-for-readable) p)
>> $2 = 1
>
> This occasionally causes problems when fetching substitutes, as can be
> seen in bug #56005 (during substitution: write_wait_fd: unimplemented).

Oh, I have not seen it but it’s weird: (guix scripts substitute) doesn’t
use O_NONBLOCK sockets, so I don’t get how it can hit that.  Needs
investigation…

Thanks,
Ludo’.

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

From: Nathan Dehnel <ncdehnel@gmail.com>

To: 56005@debbugs.gnu.org

Date: Sun, 23 Apr 2023 17:27:49 -0500

Can we please do a workaround for this until it is fixed? I can't
leave my machines while they're updating and have to keep babying
them, which is a massive waste of my time.

Specific suggestion, this flag:
--fallback         fall back to building when the substituter fails
This "unimplemented" error is a substituter failure, so if it fails it
should fall back to building the package, no? Instead the entire
command fails and the upgrade is aborted.

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

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

To: Christopher Baines <mail@cbaines.net>

Cc: ncdehnel@gmail.com, 56005@debbugs.gnu.org, 61642@debbugs.gnu.org, Simon Tournier <zimon.toutoune@gmail.com>

Subject: Re: bug#61642: intermittent write_wait_fd error when updating

Date: Wed, 03 May 2023 22:19:17 +0200

Christopher Baines <mail@cbaines.net> skribis:

> Simon Tournier <zimon.toutoune@gmail.com> writes:
>
>> Hi,
>>
>> On Mon, 20 Feb 2023 at 11:46, Christopher Baines <mail@cbaines.net> wrote:
>>
>>> It's not, since it relates to code in the (guix substitutes) module.
>>
>> Do you mean that if "https://substitutes.nonguix.org" is incorrectly
>> configured, then the code in (guix substitutes) should handle the
>> error instead of crash with a backtrace?
>
> No, but to answer your question, yes.
>
> I don't think this is a server side code/configuration issue. Also see
> this older bug for the same issue https://issues.guix.gnu.org/56005

The Guile-GnuTLS change you submitted in
<https://gitlab.com/gnutls/guile/-/merge_requests/10> may well fix this
issue.

We have yet to put out a new Guile-GnuTLS release, but we should keep an
eye on it.

Ludo’.

Send a report that this bug log contains spam.