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!