GNU bug report logs -
#45828
guix build: error: got unexpected path `Backtrace:' from substituter
Previous Next
Reported by: Leo Famulari <leo <at> famulari.name>
Date: Tue, 12 Jan 2021 22:10:01 UTC
Severity: serious
Tags: fixed
Done: Ludovic Courtès <ludo <at> gnu.org>
Bug is archived. No further changes may be made.
To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 45828 in the body.
You can then email your comments to 45828 AT debbugs.gnu.org in the normal way.
Toggle the display of automated, internal messages from the tracker.
Report forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Tue, 12 Jan 2021 22:10:01 GMT)
Full text and
rfc822 format available.
Acknowledgement sent
to
Leo Famulari <leo <at> famulari.name>
:
New bug report received and forwarded. Copy sent to
bug-guix <at> gnu.org
.
(Tue, 12 Jan 2021 22:10:01 GMT)
Full text and
rfc822 format available.
Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):
Recently, many people on the #guix IRC channel reported frequent
non-deterministic failures of any operation involving substitution, like
this:
------
$ ./pre-inst-env guix build --no-grafts poezio mpdris2 sonata beets-bandcamp beets
substitute:
guix build: error: got unexpected path `Backtrace:' from substituter
------
`guix describe` reports commit b4384e61165623b16b77b8cab16c81423c6853ed
for both my user's Guix and the guix-dameon.
Severity set to 'grave' from 'normal'
Request was from
Leo Famulari <leo <at> famulari.name>
to
control <at> debbugs.gnu.org
.
(Tue, 12 Jan 2021 22:13:02 GMT)
Full text and
rfc822 format available.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Tue, 12 Jan 2021 22:47:02 GMT)
Full text and
rfc822 format available.
Message #10 received at 45828 <at> debbugs.gnu.org (full text, mbox):
[Message part 1 (text/plain, inline)]
Leo Famulari <leo <at> famulari.name> writes:
> Recently, many people on the #guix IRC channel reported frequent
> non-deterministic failures of any operation involving substitution, like
> this:
>
> ------
> $ ./pre-inst-env guix build --no-grafts poezio mpdris2 sonata beets-bandcamp beets
> substitute:
> guix build: error: got unexpected path `Backtrace:' from substituter
> ------
>
> `guix describe` reports commit b4384e61165623b16b77b8cab16c81423c6853ed
> for both my user's Guix and the guix-dameon.
I might have managed to reproduce the error happening on the daemon
side:
→ /gnu/store/4j8vn0gbqz5adj1y02nnwcfwmqsjgj8s-guix-1.2.0-6.799f066/bin/guix substitute --query
info /gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-guix-package-cache /gnu/store/6lk8anal4s62gk3d30vgxppykbd5jcfj-guix-85e97c969 /gnu/store/9zl2zbh3q2jnbfvxgnhw8j3f637ni7z4-guix-cli /gnu/store/ihricijvy16zwkd2n671xlyrn02sqhf9-guix-manual /gnu/store/m3j427qnlp81vsdj3x9ds7s4i051r1vz-guix-system-tests /gnu/store/mbv9j7wwqvwnr5awzbi126jdsj3h64h5-guix-packages /gnu/store/n2m1ay7kpa5f4fls4vvcy46ar1fdl0wk-guix-system /gnu/store/p4q9ajlb3l7x8xglqs6fflch2iwjqwaj-guix-module-union /gnu/store/snhx33fgjj2xnc5vy96sr3c8jqw9c7s0-guix-85e97c969-modules /gnu/store/vnrlvz9pxl5qrpy5x8y51v6awz7yzn8q-guix-packages-base /gnu/store/z4wj18vyzaas2yqb0577cc3japy4fi7z-guix-config /gnu/store/zdjfbsj1a94vdbbg9r0cx4jcqnwxazxs-guix-translated-texinfo
Backtrace:
In ice-9/boot-9.scm:
1736:10 5 (with-exception-handler _ _ #:unwind? _ # _)
In unknown file:
4 (apply-smob/0 #<thunk 7f23d4f2e380>)
In ice-9/boot-9.scm:
718:2 3 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
In ice-9/eval.scm:
619:8 2 (_ #(#(#<directory (guile-user) 7f23d4b70f00>)))
In guix/ui.scm:
2127:12 1 (run-guix-command _ . _)
In guix/scripts/substitute.scm:
1256:4 0 (guix-substitute . _)
guix/scripts/substitute.scm:1256:4: In procedure guix-substitute:
Throw to key `bad-response' with args `("Bad Response-Line: ~s" (""))'.
It's hard to tell if that's actually consistent with the error
though. Repeating the same test after the restart of guix-publish on
ci.guix.gnu.org works without printing a backtrace.
[signature.asc (application/pgp-signature, inline)]
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Wed, 13 Jan 2021 00:12:01 GMT)
Full text and
rfc822 format available.
Message #13 received at 45828 <at> debbugs.gnu.org (full text, mbox):
Le Tue, 12 Jan 2021 22:46:34 +0000,
Christopher Baines <mail <at> cbaines.net> a écrit :
> Leo Famulari <leo <at> famulari.name> writes:
>
> > Recently, many people on the #guix IRC channel reported frequent
> > non-deterministic failures of any operation involving substitution,
> > like this:
> >
> > ------
> > $ ./pre-inst-env guix build --no-grafts poezio mpdris2 sonata
> > beets-bandcamp beets substitute:
> > guix build: error: got unexpected path `Backtrace:' from substituter
> > ------
> >
> > `guix describe` reports commit
> > b4384e61165623b16b77b8cab16c81423c6853ed for both my user's Guix
> > and the guix-dameon.
>
> I might have managed to reproduce the error happening on the daemon
> side:
>
> →
> /gnu/store/4j8vn0gbqz5adj1y02nnwcfwmqsjgj8s-guix-1.2.0-6.799f066/bin/guix
> substitute --query info
> /gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-guix-package-cache
> /gnu/store/6lk8anal4s62gk3d30vgxppykbd5jcfj-guix-85e97c969
> /gnu/store/9zl2zbh3q2jnbfvxgnhw8j3f637ni7z4-guix-cli
> /gnu/store/ihricijvy16zwkd2n671xlyrn02sqhf9-guix-manual
> /gnu/store/m3j427qnlp81vsdj3x9ds7s4i051r1vz-guix-system-tests
> /gnu/store/mbv9j7wwqvwnr5awzbi126jdsj3h64h5-guix-packages
> /gnu/store/n2m1ay7kpa5f4fls4vvcy46ar1fdl0wk-guix-system
> /gnu/store/p4q9ajlb3l7x8xglqs6fflch2iwjqwaj-guix-module-union
> /gnu/store/snhx33fgjj2xnc5vy96sr3c8jqw9c7s0-guix-85e97c969-modules
> /gnu/store/vnrlvz9pxl5qrpy5x8y51v6awz7yzn8q-guix-packages-base
> /gnu/store/z4wj18vyzaas2yqb0577cc3japy4fi7z-guix-config
> /gnu/store/zdjfbsj1a94vdbbg9r0cx4jcqnwxazxs-guix-translated-texinfo
> Backtrace: In ice-9/boot-9.scm: 1736:10 5 (with-exception-handler _
> _ #:unwind? _ # _) In unknown file: 4 (apply-smob/0 #<thunk
> 7f23d4f2e380>) In ice-9/boot-9.scm: 718:2 3 (call-with-prompt _ _
> 7f23d4f2e380>#<procedure default-prompt-handle…>) In ice-9/eval.scm:
> 7f23d4f2e380>619:8 2 (_ #(#(#<directory (guile-user)
> 7f23d4f2e380>7f23d4b70f00>))) In guix/ui.scm: 2127:12 1
> 7f23d4f2e380>7f23d4b70f00>(run-guix-command _ . _) In
> 7f23d4f2e380>7f23d4b70f00>guix/scripts/substitute.scm: 1256:4 0
> 7f23d4f2e380>7f23d4b70f00>(guix-substitute . _)
>
> guix/scripts/substitute.scm:1256:4: In procedure guix-substitute:
> Throw to key `bad-response' with args `("Bad Response-Line: ~s"
> (""))'.
>
>
> It's hard to tell if that's actually consistent with the error
> though. Repeating the same test after the restart of guix-publish on
> ci.guix.gnu.org works without printing a backtrace.
During the issue, I tried to manually check what berlin had to say:
$ curl https://ci.guix.gnu.org/3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo
-D-
HTTP/1.1 500 Internal Server Error Server: nginx
Date: Tue, 12 Jan 2021 22:34:01 GMT
Transfer-Encoding: chunked
Connection: keep-alive
and after the restart:
$ curl https://ci.guix.gnu.org/3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo
-D-
HTTP/1.1 404 Not Found Server: nginx
Date: Tue, 12 Jan 2021 22:34:44 GMT
Content-Type: text/plain;charset=utf-8
Content-Length: 61
Connection: keep-alive
Resource not found: /3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo
So I tried to learn more about what happens, so I put the first
response in a file, `response`. I used netcat to provide the file over
the network:
nc -l -p 8080 < response
then I tried the following:
$ guix build /gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-random
--substitute-urls=http://localhost:8080
substitute:
guix build: error: got unexpected path `Backtrace:' from substituter
Then, I restarted the daemon to pass it this substitute url:
# guix-daemon --build-users-group=guixbuild
--substitute-urls=http://localhost:8080
and from another terminal:
$ /gnu/store/wr0shvj2dy8h8w2m1pil9r9798ai6nyy-guix-command substitute
--query info
/gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-guix-package-cache
Backtrace: 2 (primitive-load "/gnu/store/wr0shvj2dy8h8w2m1pil9r9798a…")
In guix/ui.scm:
2127:12 1 (run-guix-command _ . _)
In guix/scripts/substitute.scm:
1256:4 0 (guix-substitute . _)
guix/scripts/substitute.scm:1256:4: In procedure guix-substitute:
In procedure =: Wrong type argument in position 1: #f
So my backtrace is different. For some reason, it seems that guile
cannot read anything from the body of that response, but I don't know
what's happening:
In the REPL, the following:
,m (guix scripts substitute)
(call-with-input-file "response"
(lambda (port)
(let* ((r (read-response port))
(body (response-body-port r)))
(pk 'body body 'r r)
(get-u8 body))))
Gives a backtrace:
;;; (body #<input: file 7f2394d804d0> r #<<response> version: (1 . 1)
code: 500 reason-phrase: "Internal Server Error Server: nginx" headers:
((date . #<date nanosecond: 0 second: 1 minute: 34 hour: 22 day: 12
month: 1 year: 2021 zone-offset: 0>) (transfer-encoding (chunked))
(connection keep-alive)) port: #<input: test 14>>)
ice-9/boot-9.scm:1669:16: In procedure raise-exception: In procedure =:
Wrong type argument in position 1: #f
In ice-9/ports.scm:
445:17 3 (call-with-input-file _ _ #:binary _ #:encoding _ # _)
In unknown file:
2 (get-u8 #<input: string 7f2394d804d0>)
In web/http.scm:
1978:17 1 (read! #vu8(115 99 104 101 109 101 64 40 103 117 105 …) …)
In ice-9/boot-9.scm:
1669:16 0 (raise-exception _ #:continuable? _)
HTH!
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Wed, 13 Jan 2021 11:14:01 GMT)
Full text and
rfc822 format available.
Message #16 received at 45828 <at> debbugs.gnu.org (full text, mbox):
Hello,
There are errors in "/var/log/guix-publish.log" that could be the cause
of this problem I think.
--8<---------------cut here---------------start------------->8---
GET /7m6mlzh0d6nifdxhaij7varg4q7lqdj4.narinfo
In guix/scripts/publish.scm:
482:4 7 (render-narinfo/cached #<store-connection 256.99 7f916…> …)
487:12 6 (_ . _)
In guix/store.scm:
1021:9 5 (_ #<store-connection 256.99 7f9165291230> "7m6mlzh0d6n…")
619:2 4 (write-buffered-output #<store-connection 256.99 7f9165…>)
In unknown file:
3 (force-output #<output: string 7f91644a7690>)
In guix/store.scm:
917:4 2 (write #vu8(29 0 0 0 0 0 0 0 32 0 0 0 0 0 0 0 55 109 …) …)
In unknown file:
1 (put-bytevector #<input-output: socket 14> #vu8(29 0 …) …)
In ice-9/boot-9.scm:
1669:16 0 (raise-exception _ #:continuable? _)
In procedure fport_write: Broken pipe
--8<---------------cut here---------------end--------------->8---
Thanks,
Mathieu
Severity set to 'serious' from 'grave'
Request was from
Ludovic Courtès <ludo <at> gnu.org>
to
control <at> debbugs.gnu.org
.
(Wed, 13 Jan 2021 11:48:01 GMT)
Full text and
rfc822 format available.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Wed, 13 Jan 2021 13:53:01 GMT)
Full text and
rfc822 format available.
Message #21 received at 45828 <at> debbugs.gnu.org (full text, mbox):
Hi,
Mathieu Othacehe <othacehe <at> gnu.org> skribis:
> There are errors in "/var/log/guix-publish.log" that could be the cause
> of this problem I think.
>
> GET /7m6mlzh0d6nifdxhaij7varg4q7lqdj4.narinfo
> In guix/scripts/publish.scm:
> 482:4 7 (render-narinfo/cached #<store-connection 256.99 7f916…> …)
> 487:12 6 (_ . _)
> In guix/store.scm:
> 1021:9 5 (_ #<store-connection 256.99 7f9165291230> "7m6mlzh0d6n…")
> 619:2 4 (write-buffered-output #<store-connection 256.99 7f9165…>)
> In unknown file:
> 3 (force-output #<output: string 7f91644a7690>)
> In guix/store.scm:
> 917:4 2 (write #vu8(29 0 0 0 0 0 0 0 32 0 0 0 0 0 0 0 55 109 …) …)
> In unknown file:
> 1 (put-bytevector #<input-output: socket 14> #vu8(29 0 …) …)
> In ice-9/boot-9.scm:
> 1669:16 0 (raise-exception _ #:continuable? _)
> In procedure fport_write: Broken pipe
As discussed on IRC today, the EPIPE above comes from talking to
guix-daemon, meaning that the store connection shown in the backtrace
has been closed by guix-daemon.
This can happen if guix-daemon was restarted but ‘guix publish’ wasn’t:
‘guix publish’ opens only one connection to the store at startup time,
and then never tries to re-open it. There was an old bug on this topic:
https://issues.guix.gnu.org/26705
Back then I marked it as ‘wontfix’ because:
1. Losing a connection to the daemon Does Not Happen™ in normal
conditions. Namely, upon ‘herd restart guix-daemon’, ‘guix
publish’ is automatically restarted. One situation where ‘guix
publish’ is not restarted is if one does “killall guix-daemon” or
similar. (Perhaps that’s something to fix in the Shepherd?)
2. Catching EPIPE in the right place is tricky. Basically we’d
probably need to install a 'system-error handler around each RPC
(and offer callers a way to choose the EPIPE handling strategy),
which would incur additional overhead.
Ludo’.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Wed, 13 Jan 2021 13:53:02 GMT)
Full text and
rfc822 format available.
Message #24 received at 45828 <at> debbugs.gnu.org (full text, mbox):
I forgot to mention: running “sudo herd restart guix-publish” on berlin
a couple of hours ago solved the immediate problem.
Ludo’.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Wed, 13 Jan 2021 14:03:01 GMT)
Full text and
rfc822 format available.
Message #27 received at 45828 <at> debbugs.gnu.org (full text, mbox):
Hi Chris,
Christopher Baines <mail <at> cbaines.net> skribis:
> I might have managed to reproduce the error happening on the daemon
> side:
>
> → /gnu/store/4j8vn0gbqz5adj1y02nnwcfwmqsjgj8s-guix-1.2.0-6.799f066/bin/guix substitute --query
> info /gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-guix-package-cache /gnu/store/6lk8anal4s62gk3d30vgxppykbd5jcfj-guix-85e97c969 /gnu/store/9zl2zbh3q2jnbfvxgnhw8j3f637ni7z4-guix-cli /gnu/store/ihricijvy16zwkd2n671xlyrn02sqhf9-guix-manual /gnu/store/m3j427qnlp81vsdj3x9ds7s4i051r1vz-guix-system-tests /gnu/store/mbv9j7wwqvwnr5awzbi126jdsj3h64h5-guix-packages /gnu/store/n2m1ay7kpa5f4fls4vvcy46ar1fdl0wk-guix-system /gnu/store/p4q9ajlb3l7x8xglqs6fflch2iwjqwaj-guix-module-union /gnu/store/snhx33fgjj2xnc5vy96sr3c8jqw9c7s0-guix-85e97c969-modules /gnu/store/vnrlvz9pxl5qrpy5x8y51v6awz7yzn8q-guix-packages-base /gnu/store/z4wj18vyzaas2yqb0577cc3japy4fi7z-guix-config /gnu/store/zdjfbsj1a94vdbbg9r0cx4jcqnwxazxs-guix-translated-texinfo
> Backtrace:
> In ice-9/boot-9.scm:
> 1736:10 5 (with-exception-handler _ _ #:unwind? _ # _)
> In unknown file:
> 4 (apply-smob/0 #<thunk 7f23d4f2e380>)
> In ice-9/boot-9.scm:
> 718:2 3 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
> In ice-9/eval.scm:
> 619:8 2 (_ #(#(#<directory (guile-user) 7f23d4b70f00>)))
> In guix/ui.scm:
> 2127:12 1 (run-guix-command _ . _)
> In guix/scripts/substitute.scm:
> 1256:4 0 (guix-substitute . _)
>
> guix/scripts/substitute.scm:1256:4: In procedure guix-substitute:
> Throw to key `bad-response' with args `("Bad Response-Line: ~s" (""))'.
It’s interesting that we’re not seeing 500 here, but a bad response.
I tried reproducing it locally (running “sudo killall guix-daemon” after
I had started “guix publish”, and then running a command similar to the
one above) but I failed: I get a proper 500 response, which ‘guix
substitute’ gracefully interprets as a transient error.
We could be defensive and catch 'bad-response. The problem is that
there are other exceptions thrown by (web http) et al. and they’re not
quite documented so it’s not clear to me how to do it nicely.
Thoughts?
Ludo’.
Information forwarded
to
bug-guix <at> gnu.org
:
bug#45828
; Package
guix
.
(Thu, 14 Jan 2021 09:10:01 GMT)
Full text and
rfc822 format available.
Message #30 received at 45828 <at> debbugs.gnu.org (full text, mbox):
Hey Ludo,
> 1. Losing a connection to the daemon Does Not Happen™ in normal
> conditions. Namely, upon ‘herd restart guix-daemon’, ‘guix
> publish’ is automatically restarted. One situation where ‘guix
> publish’ is not restarted is if one does “killall guix-daemon” or
> similar. (Perhaps that’s something to fix in the Shepherd?)
Thanks for explaining. That's probably what caused the issue, as I
killed a bunch of guix-daemon forked processes that I suspected to be
deadlocked.
Maybe the Shepherd should indeed kill the whole process group and
restart the service and its dependencies when the "guix-daemon" process
or one of its child is killed.
Thanks,
Mathieu
Added tag(s) fixed.
Request was from
Ludovic Courtès <ludo <at> gnu.org>
to
control <at> debbugs.gnu.org
.
(Tue, 19 Jan 2021 13:48:01 GMT)
Full text and
rfc822 format available.
bug closed, send any further explanations to
45828 <at> debbugs.gnu.org and Leo Famulari <leo <at> famulari.name>
Request was from
Ludovic Courtès <ludo <at> gnu.org>
to
control <at> debbugs.gnu.org
.
(Tue, 19 Jan 2021 13:48:01 GMT)
Full text and
rfc822 format available.
bug archived.
Request was from
Debbugs Internal Request <help-debbugs <at> gnu.org>
to
internal_control <at> debbugs.gnu.org
.
(Wed, 17 Feb 2021 12:24:07 GMT)
Full text and
rfc822 format available.
This bug report was last modified 3 years and 40 days ago.
Previous Next
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.