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

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

[Leo Famulari]

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.

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

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 2229 bytes --]


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 _ _ #<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.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]

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

[Julien Lepiller]

Le Tue, 12 Jan 2021 22:46:34 +0000,
Christopher Baines <mail@cbaines.net> a écrit :

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

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

[Mathieu Othacehe]

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

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

[Ludovic Courtès]

Hi,

Mathieu Othacehe <othacehe@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’.

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

[Ludovic Courtès]

I forgot to mention: running “sudo herd restart guix-publish” on berlin
a couple of hours ago solved the immediate problem.

Ludo’.

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

[Ludovic Courtès]

Hi Chris,

Christopher Baines <mail@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’.

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

[Mathieu Othacehe]

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