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

Leo Famulari wrote on 12 Jan 23:09 +0100

Recipients:(address . bug-guix@gnu.org)

Message-ID: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.

Leo Famulari wrote on 12 Jan 23:12 +0100

(no subject)

Recipients:(address . control@debbugs.gnu.org)

Message-ID:X/4evJ6dXqZU1sp4@jasmine.lan

severity 45828 grave

Christopher Baines wrote on 12 Jan 23:46 +0100

Re: bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter

Recipients:(name . Leo Famulari)(address . leo@famulari.name)(address . 45828@debbugs.gnu.org)

Message-ID: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.

Julien Lepiller wrote on 13 Jan 01:11 +0100

Recipients:(name . Christopher Baines)(address . mail@cbaines.net)

Message-ID: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: nginxTransfer-Encoding: chunkedConnection: keep-alive
and after the restart:
$ curl https://ci.guix.gnu.org/3c01q1f16kljfry70qjg6cs6k8winfzg.narinfo-D-HTTP/1.1 404 Not Found Server: nginxContent-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!

Mathieu Othacehe wrote on 13 Jan 12:13 +0100

Recipients:(name . Julien Lepiller)(address . julien@lepiller.eu)

Message-ID: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

Ludovic Courtès wrote on 13 Jan 12:47 +0100

Re: bug#45836: cups-service-type duplicates lp group

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87y2gxawjn.fsf@gnu.org

severity 45828 seriousdone

Ludovic Courtès wrote on 13 Jan 14:51 +0100

Re: bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter

Recipients:(name . Mathieu Othacehe)(address . othacehe@gnu.org)

Message-ID: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’.

Ludovic Courtès wrote on 13 Jan 14:52 +0100

Recipients:(name . Mathieu Othacehe)(address . othacehe@gnu.org)

Message-ID: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’.

Ludovic Courtès wrote on 13 Jan 15:02 +0100

Recipients:(name . Christopher Baines)(address . mail@cbaines.net)

Message-ID: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’.

Mathieu Othacehe wrote on 14 Jan 10:09 +0100

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)

Message-ID: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

Ludovic Courtès wrote 3 days ago

control message for bug #45828

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87o8hlhwdt.fsf@gnu.org

tags 45828 fixedclose 45828 quit

is:open	open issues
is:done	closed issues
submitter:<who>	search issue submitter
author:<who>	search by message author
date:yesterday..now	search by issue date
mdate:3m..2d	search by message date