guix build: error: got unexpected path `Backtrace:' from substituter

DoneSubmitted by Leo Famulari.
Details
5 participants
  • Julien Lepiller
  • Leo Famulari
  • Ludovic Courtès
  • Christopher Baines
  • Mathieu Othacehe
Owner
unassigned
Severity
serious
L
L
Leo Famulari wrote on 12 Jan 23:09 +0100
(address . bug-guix@gnu.org)
X/4eBHwwQ+afS3Il@jasmine.lan
Recently, many people on the #guix IRC channel reported frequentnon-deterministic failures of any operation involving substitution, likethis:
------$ ./pre-inst-env guix build --no-grafts poezio mpdris2 sonata beets-bandcamp beetssubstitute: guix build: error: got unexpected path `Backtrace:' from substituter------
`guix describe` reports commit b4384e61165623b16b77b8cab16c81423c6853edfor both my user's Guix and the guix-dameon.
L
L
Leo Famulari wrote on 12 Jan 23:12 +0100
(no subject)
(address . control@debbugs.gnu.org)
X/4evJ6dXqZU1sp4@jasmine.lan
severity 45828 grave
C
C
Christopher Baines wrote on 12 Jan 23:46 +0100
Re: bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
(name . Leo Famulari)(address . leo@famulari.name)(address . 45828@debbugs.gnu.org)
87turlai45.fsf@cbaines.net
Leo Famulari <leo@famulari.name> writes:
Toggle quote (13 lines)> 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 daemonside:
→ /gnu/store/4j8vn0gbqz5adj1y02nnwcfwmqsjgj8s-guix-1.2.0-6.799f066/bin/guix substitute --queryinfo /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-texinfoBacktrace: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 errorthough. Repeating the same test after the restart of guix-publish onci.guix.gnu.org works without printing a backtrace.
-----BEGIN PGP SIGNATURE-----
iQKlBAEBCgCPFiEEPonu50WOcg2XVOCyXiijOwuE9XcFAl/+JspfFIAAAAAALgAoaXNzdWVyLWZwckBub3RhdGlvbnMub3BlbnBncC5maWZ0aGhvcnNlbWFuLm5ldDNFODlFRUU3NDU4RTcyMEQ5NzU0RTBCMjVFMjhBMzNCMEI4NEY1NzcRHG1haWxAY2JhaW5lcy5uZXQACgkQXiijOwuE9XeAGA//f4sK5f2/I62DkqPNEI9Td/F50nAklOV9JVjuictagJ6FUwXyrFQ6nVpB19pFqYA9u5SI06YNq69jk9PzhHxOElZRJbb5GG+nORr7GHRarVFlrsvmqT5fVuGgn1QY43E3mVpadi3UqOgzqh8JBw3HF04MZTY9GxSswoXX0OvHDGYpmJSIe0EHdwEA5yZeMFcXbwvQe55P0C/Pt5Tki3TlG425xhWJwXixcX2VpxPScQKMDySieQAXs5hHmPSsrqRYELnewVamOhuKJkhWwKaNDJYJOmFCEJsserbhKdFVYQZ6d3L8VdmkrtA4WB37HED7hOy6HDfB2blS3PE5N0k0N1SA5645g07wl5R/FhMkzx4DdcynO19AjcrrYnOJRxH29lISErpUBJzNoQbC1YuAd5ae/wogLmWi+/QoY/+cPFQ6BQPRXyADpFfD8BkFHiIPWvToqTkk2lI2c/ua4HsvWZ96SNn3wNS2N+Rjy0bJ6oXOpTBps6KIy54CKAlpuH1Axg4qHMkdMevbCdWNIzVAeqtErVUZJN2G8iaCSfbPBBi3Z0awxR4LBo/0BhzSD3Syj21iqh1jTHrC8xa2FngNpD3o4EJ+4WyPSlFUKSMksoMPEkESUCe3In1QXlq9s5OwzCYuolRzWIwK2VT0hDp3oJSCMrdBDZaipGrHJ4FN5sY==nBGd-----END PGP SIGNATURE-----
J
J
Julien Lepiller wrote on 13 Jan 01:11 +0100
(name . Christopher Baines)(address . mail@cbaines.net)
20210113011135.760c4faa@tachikoma.lepiller.eu
Le Tue, 12 Jan 2021 22:46:34 +0000,Christopher Baines <mail@cbaines.net> a écrit :
Toggle quote (53 lines)> Leo Famulari <leo@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: nginxDate: Tue, 12 Jan 2021 22:34:01 GMTTransfer-Encoding: chunkedConnection: keep-alive
and after the restart:
$ curl https://ci.guix.gnu.org/3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo-D-HTTP/1.1 404 Not Found Server: nginxDate: Tue, 12 Jan 2021 22:34:44 GMTContent-Type: text/plain;charset=utf-8Content-Length: 61Connection: keep-alive
Resource not found: /3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo


So I tried to learn more about what happens, so I put the firstresponse in a file, `response`. I used netcat to provide the file overthe network:
nc -l -p 8080 < response
then I tried the following:
$ guix build /gnu/store/3c01q1f16kljfry70qjg6cs6k8winfzg-random--substitute-urls=http://localhost:8080substitute: 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-cacheBacktrace: 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 guilecannot read anything from the body of that response, but I don't knowwhat'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: 12month: 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!
M
M
Mathieu Othacehe wrote on 13 Jan 12:13 +0100
(name . Julien Lepiller)(address . julien@lepiller.eu)
87o8htum2e.fsf@gnu.org
Hello,
There are errors in "/var/log/guix-publish.log" that could be the causeof this problem I think.
Toggle snippet (18 lines)GET /7m6mlzh0d6nifdxhaij7varg4q7lqdj4.narinfoIn 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
Thanks,
Mathieu
L
L
Ludovic Courtès wrote on 13 Jan 12:47 +0100
Re: bug#45836: cups-service-type duplicates lp group
(address . control@debbugs.gnu.org)
87y2gxawjn.fsf@gnu.org
severity 45828 seriousdone
L
L
Ludovic Courtès wrote on 13 Jan 14:51 +0100
Re: bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
(name . Mathieu Othacehe)(address . othacehe@gnu.org)
87pn29aqrr.fsf@gnu.org
Hi,
Mathieu Othacehe <othacehe@gnu.org> skribis:
Toggle quote (20 lines)> 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 toguix-daemon, meaning that the store connection shown in the backtracehas 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’.
L
L
Ludovic Courtès wrote on 13 Jan 14:52 +0100
(name . Mathieu Othacehe)(address . othacehe@gnu.org)
87im81aqqc.fsf@gnu.org
I forgot to mention: running “sudo herd restart guix-publish” on berlina couple of hours ago solved the immediate problem.
Ludo’.
L
L
Ludovic Courtès wrote on 13 Jan 15:02 +0100
(name . Christopher Baines)(address . mail@cbaines.net)
87a6tdaq9j.fsf@gnu.org
Hi Chris,
Christopher Baines <mail@cbaines.net> skribis:
Toggle quote (22 lines)> 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” afterI had started “guix publish”, and then running a command similar to theone above) but I failed: I get a proper 500 response, which ‘guixsubstitute’ gracefully interprets as a transient error.
We could be defensive and catch 'bad-response. The problem is thatthere are other exceptions thrown by (web http) et al. and they’re notquite documented so it’s not clear to me how to do it nicely.
Thoughts?
Ludo’.
M
M
Mathieu Othacehe wrote on 14 Jan 10:09 +0100
(name . Ludovic Courtès)(address . ludo@gnu.org)
87pn2751gq.fsf@gnu.org
Hey Ludo,
Toggle quote (6 lines)> 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 Ikilled a bunch of guix-daemon forked processes that I suspected to bedeadlocked.
Maybe the Shepherd should indeed kill the whole process group andrestart the service and its dependencies when the "guix-daemon" processor one of its child is killed.
Thanks,
Mathieu
L
L
Ludovic Courtès wrote 43 hours ago
control message for bug #45828
(address . control@debbugs.gnu.org)
87o8hlhwdt.fsf@gnu.org
tags 45828 fixedclose 45828 quit
?