all messages for Guix-related lists mirrored at yhetil.org
 help / color / mirror / code / Atom feed
* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
@ 2021-01-12 22:09 Leo Famulari
  2021-01-12 22:46 ` Christopher Baines
  0 siblings, 1 reply; 8+ messages in thread
From: Leo Famulari @ 2021-01-12 22:09 UTC (permalink / raw)
  To: 45828

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.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-12 22:09 bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter Leo Famulari
@ 2021-01-12 22:46 ` Christopher Baines
  2021-01-13  0:11   ` Julien Lepiller
  2021-01-13 14:02   ` Ludovic Courtès
  0 siblings, 2 replies; 8+ messages in thread
From: Christopher Baines @ 2021-01-12 22:46 UTC (permalink / raw)
  To: Leo Famulari; +Cc: 45828

[-- 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 --]

^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-12 22:46 ` Christopher Baines
@ 2021-01-13  0:11   ` Julien Lepiller
  2021-01-13 11:13     ` Mathieu Othacehe
  2021-01-13 14:02   ` Ludovic Courtès
  1 sibling, 1 reply; 8+ messages in thread
From: Julien Lepiller @ 2021-01-13  0:11 UTC (permalink / raw)
  To: Christopher Baines; +Cc: 45828

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!




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-13  0:11   ` Julien Lepiller
@ 2021-01-13 11:13     ` Mathieu Othacehe
  2021-01-13 13:51       ` Ludovic Courtès
  2021-01-13 13:52       ` Ludovic Courtès
  0 siblings, 2 replies; 8+ messages in thread
From: Mathieu Othacehe @ 2021-01-13 11:13 UTC (permalink / raw)
  To: Julien Lepiller; +Cc: 45828


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




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-13 11:13     ` Mathieu Othacehe
@ 2021-01-13 13:51       ` Ludovic Courtès
  2021-01-14  9:09         ` Mathieu Othacehe
  2021-01-13 13:52       ` Ludovic Courtès
  1 sibling, 1 reply; 8+ messages in thread
From: Ludovic Courtès @ 2021-01-13 13:51 UTC (permalink / raw)
  To: Mathieu Othacehe; +Cc: 45828

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’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-13 11:13     ` Mathieu Othacehe
  2021-01-13 13:51       ` Ludovic Courtès
@ 2021-01-13 13:52       ` Ludovic Courtès
  1 sibling, 0 replies; 8+ messages in thread
From: Ludovic Courtès @ 2021-01-13 13:52 UTC (permalink / raw)
  To: Mathieu Othacehe; +Cc: 45828

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

Ludo’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-12 22:46 ` Christopher Baines
  2021-01-13  0:11   ` Julien Lepiller
@ 2021-01-13 14:02   ` Ludovic Courtès
  1 sibling, 0 replies; 8+ messages in thread
From: Ludovic Courtès @ 2021-01-13 14:02 UTC (permalink / raw)
  To: Christopher Baines; +Cc: 45828

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’.




^ permalink raw reply	[flat|nested] 8+ messages in thread

* bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter
  2021-01-13 13:51       ` Ludovic Courtès
@ 2021-01-14  9:09         ` Mathieu Othacehe
  0 siblings, 0 replies; 8+ messages in thread
From: Mathieu Othacehe @ 2021-01-14  9:09 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: 45828


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




^ permalink raw reply	[flat|nested] 8+ messages in thread

end of thread, other threads:[~2021-01-14  9:10 UTC | newest]

Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-01-12 22:09 bug#45828: guix build: error: got unexpected path `Backtrace:' from substituter Leo Famulari
2021-01-12 22:46 ` Christopher Baines
2021-01-13  0:11   ` Julien Lepiller
2021-01-13 11:13     ` Mathieu Othacehe
2021-01-13 13:51       ` Ludovic Courtès
2021-01-14  9:09         ` Mathieu Othacehe
2021-01-13 13:52       ` Ludovic Courtès
2021-01-13 14:02   ` Ludovic Courtès

Code repositories for project(s) associated with this external index

	https://git.savannah.gnu.org/cgit/guix.git

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.