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

  • Done
  • quality assurance status badge
Details
5 participants
  • Julien Lepiller
  • Leo Famulari
  • Ludovic Courtès
  • Christopher Baines
  • Mathieu Othacehe
Owner
unassigned
Submitted by
Leo Famulari
Severity
serious
L
L
Leo Famulari wrote on 12 Jan 2021 23:09
(address . bug-guix@gnu.org)
X/4eBHwwQ+afS3Il@jasmine.lan
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.
L
L
Leo Famulari wrote on 12 Jan 2021 23:12
(no subject)
(address . control@debbugs.gnu.org)
X/4evJ6dXqZU1sp4@jasmine.lan
severity 45828 grave
C
C
Christopher Baines wrote on 12 Jan 2021 23:46
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 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.
-----BEGIN PGP SIGNATURE-----

iQKlBAEBCgCPFiEEPonu50WOcg2XVOCyXiijOwuE9XcFAl/+JspfFIAAAAAALgAo
aXNzdWVyLWZwckBub3RhdGlvbnMub3BlbnBncC5maWZ0aGhvcnNlbWFuLm5ldDNF
ODlFRUU3NDU4RTcyMEQ5NzU0RTBCMjVFMjhBMzNCMEI4NEY1NzcRHG1haWxAY2Jh
aW5lcy5uZXQACgkQXiijOwuE9XeAGA//f4sK5f2/I62DkqPNEI9Td/F50nAklOV9
JVjuictagJ6FUwXyrFQ6nVpB19pFqYA9u5SI06YNq69jk9PzhHxOElZRJbb5GG+n
ORr7GHRarVFlrsvmqT5fVuGgn1QY43E3mVpadi3UqOgzqh8JBw3HF04MZTY9GxSs
woXX0OvHDGYpmJSIe0EHdwEA5yZeMFcXbwvQe55P0C/Pt5Tki3TlG425xhWJwXix
cX2VpxPScQKMDySieQAXs5hHmPSsrqRYELnewVamOhuKJkhWwKaNDJYJOmFCEJss
erbhKdFVYQZ6d3L8VdmkrtA4WB37HED7hOy6HDfB2blS3PE5N0k0N1SA5645g07w
l5R/FhMkzx4DdcynO19AjcrrYnOJRxH29lISErpUBJzNoQbC1YuAd5ae/wogLmWi
+/QoY/+cPFQ6BQPRXyADpFfD8BkFHiIPWvToqTkk2lI2c/ua4HsvWZ96SNn3wNS2
N+Rjy0bJ6oXOpTBps6KIy54CKAlpuH1Axg4qHMkdMevbCdWNIzVAeqtErVUZJN2G
8iaCSfbPBBi3Z0awxR4LBo/0BhzSD3Syj21iqh1jTHrC8xa2FngNpD3o4EJ+4WyP
SlFUKSMksoMPEkESUCe3In1QXlq9s5OwzCYuolRzWIwK2VT0hDp3oJSCMrdBDZai
pGrHJ4FN5sY=
=nBGd
-----END PGP SIGNATURE-----

J
J
Julien Lepiller wrote on 13 Jan 2021 01:11
(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:

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

-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!
M
M
Mathieu Othacehe wrote on 13 Jan 2021 12:13
(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 cause
of this problem I think.

Toggle snippet (18 lines)
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

Thanks,

Mathieu
L
L
Ludovic Courtès wrote on 13 Jan 2021 12:47
Re: bug#45836: cups-service-type duplicates lp group
(address . control@debbugs.gnu.org)
87y2gxawjn.fsf@gnu.org
severity 45828 serious
done
L
L
Ludovic Courtès wrote on 13 Jan 2021 14:51
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 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:


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 2021 14:52
(name . Mathieu Othacehe)(address . othacehe@gnu.org)
87im81aqqc.fsf@gnu.org
I forgot to mention: running “sudo herd restart guix-publish” on berlin
a couple of hours ago solved the immediate problem.

Ludo’.
L
L
Ludovic Courtès wrote on 13 Jan 2021 15:02
(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” 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’.
M
M
Mathieu Othacehe wrote on 14 Jan 2021 10:09
(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 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
L
L
Ludovic Courtès wrote on 19 Jan 2021 14:46
control message for bug #45828
(address . control@debbugs.gnu.org)
87o8hlhwdt.fsf@gnu.org
tags 45828 fixed
close 45828
quit
?