substitute server connection timeout

  • Open
  • quality assurance status badge
Details
3 participants
  • Ludovic Courtès
  • Christopher Baines
  • Mathieu Othacehe
Owner
unassigned
Submitted by
Mathieu Othacehe
Severity
important
M
M
Mathieu Othacehe wrote on 16 May 2021 19:57
(address . bug-guix@gnu.org)
87lf8e4l42.fsf@gnu.org
Hello,

We recently have a lot of those errors on Cuirass:

Toggle snippet (5 lines)
guix substitute: warning: while fetching http://141.80.167.131:5557/nar/g7ka09613k5v1vlznh87yg35905ggw51-python2-scipy-1.2.2-guile-builder: server is somewhat slow
guix substitute: warning: try `--no-substitutes' if the problem persists
guix substitute: error: connect*: Connection timed out

which means that the workers are failing to connect to the Cuirass
remote-server publish server on berlin at 141.80.167.131:5557.

Stracing this publish server shows that connection reuse seems to be
broken:

Toggle snippet (23 lines)
accept4(9, {sa_family=AF_INET, sin_port=htons(41742), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41744), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41746), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 25
accept4(9, {sa_family=AF_INET, sin_port=htons(41748), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 24
accept4(9, {sa_family=AF_INET, sin_port=htons(41750), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41752), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41754), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 25
accept4(9, {sa_family=AF_INET, sin_port=htons(41756), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41758), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 26
accept4(9, {sa_family=AF_INET, sin_port=htons(41760), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 24
accept4(9, {sa_family=AF_INET, sin_port=htons(41762), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41764), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41766), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41768), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 22
accept4(9, {sa_family=AF_INET, sin_port=htons(41770), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41772), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41774), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41776), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41778), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41780), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
accept4(9, {sa_family=AF_INET, sin_port=htons(41782), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21

Investigating it, I found that the connection is closed and opened
multiple times in the call-with-cached-connection procedure of the (guix
script substitute) module.

It looks like its because a 'bad-headers exception is raised when trying
to parse an eof object:

Toggle snippet (3 lines)
;;; (error bad-header (read-header-line #<eof>))

I'm not sure where this eof comes from. There is this comment in the
http-multiple-get procedure in (guix http-client):

Toggle snippet (10 lines)
;; Swallow networking errors that could occur due to connection reuse
;; and the like; they will be handled down the road when trying to
;; read responses.
(false-if-networking-error
(begin
(for-each (cut write-request <> buffer) batch)
(put-bytevector p (get))
(force-output p))))

which would suggest that connection reuse could cause networking errors?

What also puzzles me it that the main guix publish server on berlin does
not seem to present this issue. That would indicate that this error is
caused by how the Cuirass remote-server publish server is started or
configured.

Ludo, Chris, any idea?

I will keep searching anyway :)

Thanks,

Mathieu
C
C
Christopher Baines wrote on 16 May 2021 20:26
(name . Mathieu Othacehe)(address . othacehe@gnu.org)
87eee6cz75.fsf@cbaines.net
Mathieu Othacehe <othacehe@gnu.org> writes:

Toggle quote (74 lines)
> Hello,
>
> We recently have a lot of those errors on Cuirass:
>
> --8<---------------cut here---------------start------------->8---
> guix substitute: warning: while fetching http://141.80.167.131:5557/nar/g7ka09613k5v1vlznh87yg35905ggw51-python2-scipy-1.2.2-guile-builder: server is somewhat slow
> guix substitute: warning: try `--no-substitutes' if the problem persists
> guix substitute: error: connect*: Connection timed out
> --8<---------------cut here---------------end--------------->8---
>
> which means that the workers are failing to connect to the Cuirass
> remote-server publish server on berlin at 141.80.167.131:5557.
>
> Stracing this publish server shows that connection reuse seems to be
> broken:
>
> --8<---------------cut here---------------start------------->8---
> accept4(9, {sa_family=AF_INET, sin_port=htons(41742), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41744), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41746), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 25
> accept4(9, {sa_family=AF_INET, sin_port=htons(41748), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 24
> accept4(9, {sa_family=AF_INET, sin_port=htons(41750), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41752), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41754), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 25
> accept4(9, {sa_family=AF_INET, sin_port=htons(41756), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41758), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 26
> accept4(9, {sa_family=AF_INET, sin_port=htons(41760), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 24
> accept4(9, {sa_family=AF_INET, sin_port=htons(41762), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41764), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41766), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41768), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 22
> accept4(9, {sa_family=AF_INET, sin_port=htons(41770), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41772), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41774), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41776), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41778), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41780), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> accept4(9, {sa_family=AF_INET, sin_port=htons(41782), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
> --8<---------------cut here---------------end--------------->8---
>
> Investigating it, I found that the connection is closed and opened
> multiple times in the call-with-cached-connection procedure of the (guix
> script substitute) module.
>
> It looks like its because a 'bad-headers exception is raised when trying
> to parse an eof object:
>
> --8<---------------cut here---------------start------------->8---
> ;;; (error bad-header (read-header-line #<eof>))
> --8<---------------cut here---------------end--------------->8---
>
> I'm not sure where this eof comes from. There is this comment in the
> http-multiple-get procedure in (guix http-client):
>
> --8<---------------cut here---------------start------------->8---
> ;; Swallow networking errors that could occur due to connection reuse
> ;; and the like; they will be handled down the road when trying to
> ;; read responses.
> (false-if-networking-error
> (begin
> (for-each (cut write-request <> buffer) batch)
> (put-bytevector p (get))
> (force-output p))))
> --8<---------------cut here---------------end--------------->8---
>
> which would suggest that connection reuse could cause networking errors?
>
> What also puzzles me it that the main guix publish server on berlin does
> not seem to present this issue. That would indicate that this error is
> caused by how the Cuirass remote-server publish server is started or
> configured.
>
> Ludo, Chris, any idea?

While I've been working in this area, I've actually been trying to pick
apart the connection caching, since the single thread assumption doesn't
hold in the Guix Build Coordinator.

Anyway, I do have a theory. Assuming I'm correct in saying that there's
no nginx between the client and publish server here, I think that's your
configuration difference.

For ci.guix.gnu.org, as well as data.guix.gnu.org, it's NGinx which is
keeping connections alive. I'm not sure the Guile code for the publish
server does similarly, so talking to it directly might be different.

That's on the server side, the actual problem is probably on the client
side, as I guess there are possibly places where closed connections
aren't handled properly. This reminds me I sent some patches relating to
closing connections, this could well be related [1].

-----BEGIN PGP SIGNATURE-----

iQKlBAEBCgCPFiEEPonu50WOcg2XVOCyXiijOwuE9XcFAmChY89fFIAAAAAALgAo
aXNzdWVyLWZwckBub3RhdGlvbnMub3BlbnBncC5maWZ0aGhvcnNlbWFuLm5ldDNF
ODlFRUU3NDU4RTcyMEQ5NzU0RTBCMjVFMjhBMzNCMEI4NEY1NzcRHG1haWxAY2Jh
aW5lcy5uZXQACgkQXiijOwuE9XfG9w/+KvzCHwfnB+eeEd6i0xTvTfc8+oLxb+GS
j1TSbXSGR02ByGMGIbJeAMmNPV20V9Lzi24a49451fskUZbCGeg6aS2rO3c9QpUX
jbF7//NW8zwgmhO/Hh9dvB4v+q01+VwrzE3c6ssAVO6772ZrTJqGA7oCU9UqD1w6
dQYUto8iSxa95UhFcNFMtGcBAevdoN4Ku9OpkqIt8uViCED+YM6a9Ej4d9f9oC8h
vxw6EU0YsCrobJQJ8KW56N9uR4oeI4IqWevou2LbSAmcHEWmGHAF6XDgxu0594Ip
YOFuqso4nuRxU3ffzgEupMbJA07yrwf0EB4lreqsSfU8gtZupFMLgyc8PviyXjw3
XPpo3PAukKhsVZyQlnTc6ldatWWVHIeTPy8vxdr6GvSQnzliaQmzpHj7xVqkfS3f
R1gz5hEXoS0o/CXpVkpnaYMC8m+Y2ujM5AbEUBVo6itR6mmUCCF5D9q/BtosjQvu
8wrLes42iAqwlnNeg8UGKra/cwJ0YGVrOInsOyXX97jz3UVjkxV7jq53+vkw3fGZ
eyHDugAJ8DKw9js8BX88AmXaV/Art4M0qG6D6Zp+MvIUbU9z+oNeTjAXgGewxntw
sfIdxHju+DNs5x5je3pTzyRSDPEfle8Xvd58DbGyAIoP8v7C7LYPmxVID7R0D/cs
ccIQKCj/kqg=
=yVQQ
-----END PGP SIGNATURE-----

M
M
Mathieu Othacehe wrote on 17 May 2021 16:49
(name . Christopher Baines)(address . mail@cbaines.net)
87eee59zzm.fsf@gnu.org
Hey,

Toggle quote (5 lines)
> That's on the server side, the actual problem is probably on the client
> side, as I guess there are possibly places where closed connections
> aren't handled properly. This reminds me I sent some patches relating to
> closing connections, this could well be related [1].

Oh, you're right, the Nginx server probably makes the difference
here. The http-write procedure of the Guile (web server http) module
seems to handle keep-alive connections. However, the wrapping http-write
procedure of (guix scripts publish) may not.

I'll have a closer look, thanks for your help.

Mathieu
M
M
Mathieu Othacehe wrote on 18 May 2021 16:35
(name . Christopher Baines)(address . mail@cbaines.net)
878s4c85zu.fsf@gnu.org
Hey,

Toggle quote (2 lines)
> I'll have a closer look, thanks for your help.

So this snippet in the http-write procedure of the (guix scripts
publish) module:

Toggle snippet (4 lines)
(swallow-zlib-error
(close-port port))

is closing the client port unconditionally, which means that guix
publish cannot keep connections alive, unless sitting behind an Nginx
proxy.

I'm trying to turn the close-port call into a maybe-close-port with the
following procedure:

Toggle snippet (8 lines)
(define (maybe-close-port port)
(cond
((keep-alive? response)
(poll-set-add! (http-poll-set server) port *events*))
(else
(close-port port))))

however this is terribly hacky, as I need to access the private poll-set
from (web server http).

Ludo, do you have a better idea?

Thanks,

Mathieu
M
L
L
Ludovic Courtès wrote on 29 May 2021 23:04
control message for bug #48468
(address . control@debbugs.gnu.org)
877djh5k0g.fsf@gnu.org
severity 48468 important
quit
L
L
Ludovic Courtès wrote on 29 May 2021 23:44
Re: bug#48468: substitute server connection timeout
(name . Christopher Baines)(address . mail@cbaines.net)
87v97143lo.fsf@gnu.org
Hi,

Christopher Baines <mail@cbaines.net> skribis:

Toggle quote (2 lines)
> Mathieu Othacehe <othacehe@gnu.org> writes:

[...]

Toggle quote (10 lines)
>> Stracing this publish server shows that connection reuse seems to be
>> broken:
>>
>> --8<---------------cut here---------------start------------->8---
>> accept4(9, {sa_family=AF_INET, sin_port=htons(41742), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
>> accept4(9, {sa_family=AF_INET, sin_port=htons(41744), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21
>> accept4(9, {sa_family=AF_INET, sin_port=htons(41746), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 25
>> accept4(9, {sa_family=AF_INET, sin_port=htons(41748), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 24
>> accept4(9, {sa_family=AF_INET, sin_port=htons(41750), sin_addr=inet_addr("141.80.167.185")}, [112->16], 0) = 21

Ouch.

Toggle quote (27 lines)
>> Investigating it, I found that the connection is closed and opened
>> multiple times in the call-with-cached-connection procedure of the (guix
>> script substitute) module.
>>
>> It looks like its because a 'bad-headers exception is raised when trying
>> to parse an eof object:
>>
>> --8<---------------cut here---------------start------------->8---
>> ;;; (error bad-header (read-header-line #<eof>))
>> --8<---------------cut here---------------end--------------->8---
>>
>> I'm not sure where this eof comes from. There is this comment in the
>> http-multiple-get procedure in (guix http-client):
>>
>> --8<---------------cut here---------------start------------->8---
>> ;; Swallow networking errors that could occur due to connection reuse
>> ;; and the like; they will be handled down the road when trying to
>> ;; read responses.
>> (false-if-networking-error
>> (begin
>> (for-each (cut write-request <> buffer) batch)
>> (put-bytevector p (get))
>> (force-output p))))
>> --8<---------------cut here---------------end--------------->8---
>>
>> which would suggest that connection reuse could cause networking errors?

[...]

Toggle quote (4 lines)
> That's on the server side, the actual problem is probably on the client
> side, as I guess there are possibly places where closed connections
> aren't handled properly.

D’oh. So we should be able to use it by talking to a bare ‘guix
publish’? I tried and failed to reproduce it, but that’s probably not
deterministic.

Toggle quote (5 lines)
> This reminds me I sent some patches relating to closing connections,
> this could well be related [1].
>
> 1: https://issues.guix.gnu.org/47174

This one will properly close connections when the servers asks for it,
but would that make a difference?

Thanks,
Ludo’.
L
L
Ludovic Courtès wrote on 18 Jun 2021 14:33
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87im2bfj3i.fsf@gnu.org
Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (24 lines)
> Investigating it, I found that the connection is closed and opened
> multiple times in the call-with-cached-connection procedure of the (guix
> script substitute) module.
>
> It looks like its because a 'bad-headers exception is raised when trying
> to parse an eof object:
>
> ;;; (error bad-header (read-header-line #<eof>))
>
>
> I'm not sure where this eof comes from. There is this comment in the
> http-multiple-get procedure in (guix http-client):
>
> ;; Swallow networking errors that could occur due to connection reuse
> ;; and the like; they will be handled down the road when trying to
> ;; read responses.
> (false-if-networking-error
> (begin
> (for-each (cut write-request <> buffer) batch)
> (put-bytevector p (get))
> (force-output p))))
>
> which would suggest that connection reuse could cause networking errors?

Trying to see exactly which bit is at fault here. First,
‘http-multiple-get’ seems to be working as expected when passed a fresh
connection:

Toggle snippet (15 lines)
scheme@(guix http-client)> (http-multiple-get (string->uri "https://ci.guix.gnu.org")
(lambda (request response port result)
(get-bytevector-n port (response-content-length response))
(cons #t result))
'()
(make-list
5000
(build-request (build-uri 'https
#:host "ci.guix.gnu.org"
#:path "/d7gpr41qpsifri54vp2lzjs99zkylscq.narinfo"))))
connecting (5000 requests left)...connecting (4400 requests left)...connecting (3800 requests left)...connecting (3200 requests left)...connecting (2600 requests left)...connecting (2000 requests left)...connecting (1400 requests left)...connecting (800 requests left)...connecting (200 requests left)...$143 = (#t #t …)
scheme@(guix http-client)> (length $143)
$144 = 5000

But maybe I’m not looking at the right thing.

Do you have evidence or a reproducer?

Thanks,
Ludo’.
M
M
Mathieu Othacehe wrote on 29 Jun 2021 18:49
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87sg108vl5.fsf@gnu.org
Hey,

Toggle quote (4 lines)
> But maybe I’m not looking at the right thing.
>
> Do you have evidence or a reproducer?

Yes, adding the following debug message here:

Toggle snippet (12 lines)
--- a/guix/scripts/substitute.scm
+++ b/guix/scripts/substitute.scm
@@ -416,6 +416,7 @@ server certificates."
;; and retry. We might also get 'bad-response or a similar
;; exception from (web response) later on, once we've sent the
;; request, or a ERROR/INVALID-SESSION from GnuTLS.
+ (pk key args)
(if (or (and (eq? key 'system-error)
(= EPIPE (system-error-errno `(,key ,@args))))
(and (eq? key 'gnutls-error)

and using substitutes from a publish server without keep alive support
(before 0b8fa24), prints something like:

Toggle snippet (14 lines)
downloading from http://192.168.1.51:8080/nar/gzip/lkmiyfzi1bq571yn4gypbcs5vn4fpma7-texlive-cm-51265 ...
texlive-cm-51265 7.8MiB/s 00:00 | 1.7MiB transferred

substituting /gnu/store/l788x07ska5vffayz0gayv4hsx5flxal-module-import-compiled...

;;; (bad-header (read-header-line #<eof>))
downloading from http://192.168.1.51:8080/nar/gzip/l788x07ska5vffayz0gayv4hsx5flxal-module-import-compiled ...
module-import-compiled 7.5MiB/s 00:00 | 85KiB transferred

substituting /gnu/store/1s1lrnxlkjwxshk5q2w97ig3clc6n06f-ruby-2.6.5...

;;; (bad-header (read-header-line #<eof>))

That's because the connection is closed by the publish server each time
a NAR is sent. This particular behaviour is fixed by:

I hoped that it would decrease the load of the Cuirass publish server
that was flooded by worker connections. While the situation is better,
there are still a lot of substitute timeout errors on Cuirass.

I have also observed those timeouts using the publish server behind
ci.guix.gnu.org. This makes me think that there's something else that is
preventing the server from honoring every connection request in less
than 5 seconds (the timeout duration).

Thanks,

Mathieu
L
L
Ludovic Courtès wrote on 5 Dec 2022 14:21
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87lenmrnos.fsf@gnu.org
Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (9 lines)
> I hoped that it would decrease the load of the Cuirass publish server
> that was flooded by worker connections. While the situation is better,
> there are still a lot of substitute timeout errors on Cuirass.
>
> I have also observed those timeouts using the publish server behind
> ci.guix.gnu.org. This makes me think that there's something else that is
> preventing the server from honoring every connection request in less
> than 5 seconds (the timeout duration).

I don’t see this when substituting from https://ci.guix.gnu.orgthese
days.

You mentioned on IRC that nginx logs show that ‘guix publish’ times out.
Looking at /var/log/nginx/error.log, I see “Connection reset by peer”
and “Broken pipe”, which could indicate that the client closed the
connection (which was open) prematurely, maybe due to an internal
timeout.

What I’d like to know is whether those timeouts you mention appear
during connection establishment (connect(2) on the client side doesn’t
complete within 5 seconds) or after connection establishment.

Connection establishment is handled by the kernel and ‘guix publish’ is
not involved. However, the listen(2) call made in (web server http)
sets a maximum backlog of 128 connections; if at some point 128
connections are already queued, then the 129th client will have
connect(2) take some time. Seems unlikely, but who knows.

Ludo’.
M
M
Mathieu Othacehe wrote on 7 Dec 2022 10:44
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87cz8v8s66.fsf@gnu.org
Hello,

Toggle quote (6 lines)
> You mentioned on IRC that nginx logs show that ‘guix publish’ times out.
> Looking at /var/log/nginx/error.log, I see “Connection reset by peer”
> and “Broken pipe”, which could indicate that the client closed the
> connection (which was open) prematurely, maybe due to an internal
> timeout.

Could it be that the client is receiving 404 because the baking of some
NAR was deferred to a worker, and then it closes the connection?

I think that's what I had in mind with the patch 2/2 of this patchset:

Thanks,

Mathieu
L
L
Ludovic Courtès wrote on 7 Dec 2022 14:38
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87cz8vjpv2.fsf@gnu.org
Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (9 lines)
>> You mentioned on IRC that nginx logs show that ‘guix publish’ times out.
>> Looking at /var/log/nginx/error.log, I see “Connection reset by peer”
>> and “Broken pipe”, which could indicate that the client closed the
>> connection (which was open) prematurely, maybe due to an internal
>> timeout.
>
> Could it be that the client is receiving 404 because the baking of some
> NAR was deferred to a worker, and then it closes the connection?

Unlikely. Take
/gnu/store/qmzr030rzgikdxv3g9msqv0l8qp5j6y2-btrfs-raid-root-os.drv,
which was marked as failed earlier today due to missing .drv. It’s a
4KiB file, and the cache-bypass-threshold is ‘guix publish’ is typically
set to something much higher than that. So ‘guix publish’ won’t return
404 in that case.

If you find a “missing derivation” error in Cuirass, how would you
search logs to find what happened? I’m not sure where to look for
useful debugging info.

Thanks,
Ludo’.
M
M
Mathieu Othacehe wrote on 7 Dec 2022 15:31
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
878rjj8eun.fsf@gnu.org
Hello,

Toggle quote (6 lines)
> /gnu/store/qmzr030rzgikdxv3g9msqv0l8qp5j6y2-btrfs-raid-root-os.drv,
> which was marked as failed earlier today due to missing .drv. It’s a
> 4KiB file, and the cache-bypass-threshold is ‘guix publish’ is typically
> set to something much higher than that. So ‘guix publish’ won’t return
> 404 in that case.

Yes but that derivation also depends on other derivations, for instance
qemu-minimal and if I try:

Toggle snippet (5 lines)
mathieu@berlin ~$ guix build qemu-minimal
...
/gnu/store/lwv2pl0m6dkf6bkzip755w5p71g5akq4-qemu-minimal-7.1.0

and then, from my machine.

Toggle snippet (4 lines)
curl https://ci.guix.gnu.org/lwv2pl0m6dkf6bkzip755w5p71g5akq4.narinfo
We're baking it: /lwv2pl0m6dkf6bkzip755w5p71g5akq4.narinfo

wget exhibits the same behaviour and returns 404.

So any build that requires a heavy substitute, heavier than the cache
bypass threshold at least, will fail on the workers, as it would fail
locally.

That's not really a surprise as baking substitutes takes time and there
is a time window between the moment Cuirass triggers NAR baking and the
moment the NAR is baked, where every user will get a 404.

Mathieu
L
L
Ludovic Courtès wrote on 8 Dec 2022 11:26
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87wn72fay3.fsf@gnu.org
Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (19 lines)
>> /gnu/store/qmzr030rzgikdxv3g9msqv0l8qp5j6y2-btrfs-raid-root-os.drv,
>> which was marked as failed earlier today due to missing .drv. It’s a
>> 4KiB file, and the cache-bypass-threshold is ‘guix publish’ is typically
>> set to something much higher than that. So ‘guix publish’ won’t return
>> 404 in that case.
>
> Yes but that derivation also depends on other derivations, for instance
> qemu-minimal and if I try:
>
> mathieu@berlin ~$ guix build qemu-minimal
> ...
> /gnu/store/lwv2pl0m6dkf6bkzip755w5p71g5akq4-qemu-minimal-7.1.0
>
>
> and then, from my machine.
>
> curl https://ci.guix.gnu.org/lwv2pl0m6dkf6bkzip755w5p71g5akq4.narinfo
> We're baking it: /lwv2pl0m6dkf6bkzip755w5p71g5akq4.narinfo

Yes, but derivations (.drv) are depend only on “sources” (like
*-guile-builder, *.patch, *.scm) and on other derivations, all of which
are typically less than 1 MiB.

Derivations don’t depend on derivation outputs like that of qemu-minimal
above.

Toggle quote (4 lines)
> So any build that requires a heavy substitute, heavier than the cache
> bypass threshold at least, will fail on the workers, as it would fail
> locally.

The main ‘guix publish’ instance on berlin has cache-bypass-threshold
set to 100 MiB; I don’t think we have any source or .drv that is this
big, or even a tenth of it. :-)

The ‘guix publish’ instance spawned in (cuirass remote) doesn’t use
caching at all, so there’s no bypass threshold.

The only clue we have so far is a long chain of successful .drv
substitutions followed by a failing one:

Toggle snippet (19 lines)
Downloading http://141.80.167.131/nar/zstd/9nm35401i8j42559iadi3iz3kmhmj7pr-guix-system-tests.drv...

[K guix-system-tests.drv 1KiB 0B/s 00:00 [ ] 0.0%
[K guix-system-tests.drv 1KiB 1.3MiB/s 00:00 [##################] 100.0%
[K guix-system-tests.drv 1KiB 408KiB/s 00:00 [##################] 100.0%

@ substituter-succeeded /gnu/store/9nm35401i8j42559iadi3iz3kmhmj7pr-guix-system-tests.drv
fetching path `/gnu/store/9zf6inizcb09m136c44dj35fmzf2g3hs-guix-system-tests-modules.drv'...
@ substituter-started /gnu/store/9zf6inizcb09m136c44dj35fmzf2g3hs-guix-system-tests-modules.drv substitute
Downloading http://141.80.167.131/nar/zstd/9zf6inizcb09m136c44dj35fmzf2g3hs-guix-system-tests-modules.drv...

[K guix-system-tests-modules.drv 543B 0B/s 00:00 [ ] 0.0%
[K guix-system-tests-modules.drv 543B 851KiB/s 00:00 [##################] 100.0%
[K guix-system-tests-modules.drv 543B 484KiB/s 00:00 [##################] 100.0%

@ substituter-succeeded /gnu/store/9zf6inizcb09m136c44dj35fmzf2g3hs-guix-system-tests-modules.drv
cannot build missing derivation ?/gnu/store/zq7idl0j51fdzqhhqm9ql90d0f2326k7-btrfs-root-on-subvolume-os.drv?


Plausible explanations that come to mind:

1. ‘guix publish’ returning 404, but not due to baking. Instead the
.drv is simply not in store, hence 404.

2. Client timeout (‘guix publish’ fails to reply on time).

3. Cached 404 in nginx (though we’re not supposed to cache those I
think?), or timeout in nginx (again due to ‘guix publish’ being too
slow and ‘proxy_read_timeout’ is reached, currently 10s).

We should see if we can get useful info from nginx/publish logs.

Thanks,
Ludo’.
L
L
Ludovic Courtès wrote on 10 Dec 2022 11:55
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87fsdn5xzb.fsf@gnu.org
Hi,

Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (2 lines)
> Mathieu Othacehe <othacehe@gnu.org> skribis:

[...]

Toggle quote (18 lines)
>> We're baking it: /lwv2pl0m6dkf6bkzip755w5p71g5akq4.narinfo
>
> Yes, but derivations (.drv) are depend only on “sources” (like
> *-guile-builder, *.patch, *.scm) and on other derivations, all of which
> are typically less than 1 MiB.
>
> Derivations don’t depend on derivation outputs like that of qemu-minimal
> above.
>
>> So any build that requires a heavy substitute, heavier than the cache
>> bypass threshold at least, will fail on the workers, as it would fail
>> locally.
>
> The main ‘guix publish’ instance on berlin has cache-bypass-threshold
> set to 100 MiB; I don’t think we have any source or .drv that is this
> big, or even a tenth of it. :-)

On closer inspection, we do get bigger sources for those system test
derivations:

Toggle snippet (13 lines)
$ du $(guix gc -R /gnu/store/2laznragkfjf0jn6n7b8c53vgmb8maqp-installed-extlinux-os.drv ) |sort -k1 -n |tail
6304 /gnu/store/mvvf60w8p0lx8vlixryb1a1gfib401rf-guix-b129026/gnu/packages
6956 /gnu/store/9cs4i3hygldsan8ahf0p7x5kgzmqz9gr-guix-packages-base-source/gnu/packages/patches
7000 /gnu/store/mvvf60w8p0lx8vlixryb1a1gfib401rf-guix-b129026/gnu
7716 /gnu/store/z0gc56x1w83wn0pi4mz8nhyjdr0d10fs-guix
12352 /gnu/store/mvvf60w8p0lx8vlixryb1a1gfib401rf-guix-b129026
22548 /gnu/store/ky96vygv1hpa8iz6677qz96binbz201h-packages
22684 /gnu/store/rrg9ki4bdjffvmgapjcqwjwjwkhb0qhl-doc
39516 /gnu/store/9cs4i3hygldsan8ahf0p7x5kgzmqz9gr-guix-packages-base-source/gnu/packages
39524 /gnu/store/9cs4i3hygldsan8ahf0p7x5kgzmqz9gr-guix-packages-base-source/gnu
39528 /gnu/store/9cs4i3hygldsan8ahf0p7x5kgzmqz9gr-guix-packages-base-source

The items at the bottom weigh around 40 MiB.

That’s still below the 100 MiB cache bypass threshold of the main ‘guix
publish’ instance though.

Ludo’.
M
M
Mathieu Othacehe wrote on 27 Dec 2022 10:52
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87sfh1mavg.fsf@gnu.org
Hey Ludo,

Toggle quote (3 lines)
> That’s still below the 100 MiB cache bypass threshold of the main ‘guix
> publish’ instance though.

Right. Just to be on the safe side here, what about applying this patch
to have log lines when we are replying 404 due to baking?

Thanks,

Mathieu
From 725d5ba21a0fc0108b60c37bbc8d947fab6ac938 Mon Sep 17 00:00:00 2001
From: Mathieu Othacehe <othacehe@gnu.org>
Date: Tue, 27 Dec 2022 10:49:04 +0100
Subject: [PATCH 1/1] scripts: publish: Add a log when replying 404 due to
baking.

* guix/scripts/publish.scm (render-narinfo/cached): Add it.
---
guix/scripts/publish.scm | 10 +++++++---
1 file changed, 7 insertions(+), 3 deletions(-)

Toggle diff (23 lines)
diff --git a/guix/scripts/publish.scm b/guix/scripts/publish.scm
index 3bf3bd9c7c..a2048c98fd 100644
--- a/guix/scripts/publish.scm
+++ b/guix/scripts/publish.scm
@@ -586,9 +586,13 @@ (define (delete-entry narinfo)
#:ttl 300 ;temporary
#:nar-path nar-path
#:compressions compressions)
- (not-found request
- #:phrase "We're baking it"
- #:ttl 300))) ;should be available within 5m
+ (begin
+ (format #t (G_ "~a ~a: 404 (baking)~%")
+ (request-method request)
+ (uri-path (request-uri request)))
+ (not-found request
+ #:phrase "We're baking it"
+ #:ttl 300)))) ;should be available within 5m
(else
(not-found request #:phrase "" #:ttl negative-ttl)))))
--
2.38.1
M
M
Mathieu Othacehe wrote on 28 Dec 2022 15:23
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87v8lvsj3a.fsf@gnu.org
Hello,

So I had an other look to that one,

Toggle quote (13 lines)
>
> Plausible explanations that come to mind:
>
> 1. ‘guix publish’ returning 404, but not due to baking. Instead the
> .drv is simply not in store, hence 404.
>
> 2. Client timeout (‘guix publish’ fails to reply on time).
>
> 3. Cached 404 in nginx (though we’re not supposed to cache those I
> think?), or timeout in nginx (again due to ‘guix publish’ being too
> slow and ‘proxy_read_timeout’ is reached, currently 10s).

similar to the one linked above. Some derivations are successfully
substituted then, one is not and it aborts.

This build stopped at 2022/12/24 00:25:38 CET. At that time the nginx error
log on Berlin looks like:

Toggle snippet (11 lines)
2022/12/24 00:25:23 [info] 128755#0: *178076209 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /x3c2f9zzxhk0ci81nrdsxzglp4b1h3di.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/x3c2f9zzxhk0ci81nrdsxzglp4b1h3di.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:24 [info] 128742#0: *178076816 client 174.59.221.51 closed keepalive connection
2022/12/24 00:25:25 [info] 128755#0: *178076830 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /vx7lgvrcw6i6r0inw513qn6fj3cb27mm.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/vx7lgvrcw6i6r0inw513qn6fj3cb27mm.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:26 [info] 128742#0: *178077436 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /b1g8vyqp8c52yk6vscdvjflci5mnladq.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/b1g8vyqp8c52yk6vscdvjflci5mnladq.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:28 [info] 128742#0: *178078045 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /007zgflsl5xkr377wpakbsis5c2yqh1q.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/007zgflsl5xkr377wpakbsis5c2yqh1q.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:32 [info] 128742#0: *178078659 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /xdfyi8jki350i8njk1glrzg9p0va18vy.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/xdfyi8jki350i8njk1glrzg9p0va18vy.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:33 [info] 128741#0: *178079271 recv() failed (104: Connection reset by peer) while sending to client, client: 78.47.68.4, server: ci.guix.gnu.org, request: "GET /rzs7jiwhyls2bg8zv2g1vmmgcfwkvaax.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/rzs7jiwhyls2bg8zv2g1vmmgcfwkvaax.narinfo", host: "ci.guix.gnu.org"
2022/12/24 00:25:36 [info] 128741#0: *178080049 client 157.55.39.212 closed keepalive connection
2022/12/24 00:25:38 [info] 128741#0: *178080047 peer closed connection in SSL handshake while SSL handshaking, client: 127.0.0.1, server: 0.0.0.0:443

That would, in that specific case, invalidate your hypothesis number
2. When 'guix publish' timeouts, we have messages like:

Toggle snippet (3 lines)
2022/12/24 00:45:36 [error] 128749#0: *178225211 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 86.87.253.49, server: ci.guix.gnu.org, request: "GET /m0hqyvj8di41xlraz087kmpr38zaw90r.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/m0hqyvj8di41xlraz087kmpr38zaw90r.narinfo", host: "ci.guix.gnu.org"

However, like suggested in your hypothesis number 1, it seems instead
that we are replying 404 to the worker which resets the connection. As
we have put aside the baking thing, the question is now why are those
derivations not available?

Are they not part of Berlin's store at that time? Or is the publish
server erroneously returns 404?

It looks like the requested derivations are still absent, as of right
now:

Toggle snippet (8 lines)
mathieu@berlin /var/log/nginx$ ls /gnu/store/vx7lgvrcw6i6r0inw513qn6fj3cb27mm*
ls: cannot access '/gnu/store/vx7lgvrcw6i6r0inw513qn6fj3cb27mm*': No such file or directory
mathieu@berlin /var/log/nginx$ ls /gnu/store/b1g8vyqp8c52yk6vscdvjflci5mnladq*
ls: cannot access '/gnu/store/b1g8vyqp8c52yk6vscdvjflci5mnladq*': No such file or directory
mathieu@berlin /var/log/nginx$ ls /gnu/store/007zgflsl5xkr377wpakbsis5c2yqh1q*
ls: cannot access '/gnu/store/007zgflsl5xkr377wpakbsis5c2yqh1q*': No such file or directory

As I don't have much clue about what are those derivations, I think we
should instrument a bit the publish server and maybe the substitute
script like proposed in the attachments.

WDYT?

Thanks,

Mathieu
From 9f9c839937ac2edd1b5901b2262c4be0954fa20c Mon Sep 17 00:00:00 2001
From: Mathieu Othacehe <othacehe@gnu.org>
Date: Wed, 28 Dec 2022 15:12:46 +0100
Subject: [PATCH 1/2] scripts: publish: Add a custom baking header.

Log the not-found responses and their reason (baking or not) to stdout. Also
send the X-Baking custom header so that the client can be informed of the
cause of the failure.

* guix/scripts/publish.scm (not-found): Add a baking? argument to add the
X-Baking HTTP header to the response if baking is in progress. Also, log the
404 responses to stdout, indicating if it is due to baking or not.
(render-narinfo/cached): Pass the baking? argument.
---
guix/scripts/publish.scm | 25 ++++++++++++++++++++-----
1 file changed, 20 insertions(+), 5 deletions(-)

Toggle diff (56 lines)
diff --git a/guix/scripts/publish.scm b/guix/scripts/publish.scm
index 3bf3bd9c7c..11fedf092e 100644
--- a/guix/scripts/publish.scm
+++ b/guix/scripts/publish.scm
@@ -4,7 +4,7 @@
;;; Copyright © 2015-2022 Ludovic Courtès <ludo@gnu.org>
;;; Copyright © 2020 Maxim Cournoyer <maxim.cournoyer@gmail.com>
;;; Copyright © 2021 Simon Tournier <zimon.toutoune@gmail.com>
-;;; Copyright © 2021 Mathieu Othacehe <othacehe@gnu.org>
+;;; Copyright © 2021, 2022 Mathieu Othacehe <othacehe@gnu.org>
;;;
;;; This file is part of GNU Guix.
;;;
@@ -375,14 +375,28 @@ (define* (narinfo-string store store-path
compression)))
compressions))))
+;; Custom header to indicate that baking is in progress.
+(declare-opaque-header! "X-Baking")
+
(define* (not-found request
- #:key (phrase "Resource not found")
+ #:key
+ baking?
+ (phrase "Resource not found")
ttl)
"Render 404 response for REQUEST."
+ (format #t (G_ "? ~a ~a: 404~a~%")
+ (request-method request)
+ (uri-path (request-uri request))
+ (if baking? " (baking)" ""))
(values (build-response #:code 404
- #:headers (if ttl
- `((cache-control (max-age . ,ttl)))
- '()))
+ #:headers
+ (append
+ (if ttl
+ `((cache-control (max-age . ,ttl)))
+ '())
+ (if baking?
+ '((x-baking . "1"))
+ '())))
(string-append phrase ": "
(uri-path (request-uri request)))))
@@ -587,6 +601,7 @@ (define (delete-entry narinfo)
#:nar-path nar-path
#:compressions compressions)
(not-found request
+ #:baking? #t
#:phrase "We're baking it"
#:ttl 300))) ;should be available within 5m
(else
--
2.38.1
From 25ffc57864dbf34ca58741f89c1f790dbde6702f Mon Sep 17 00:00:00 2001
From: Mathieu Othacehe <othacehe@gnu.org>
Date: Wed, 28 Dec 2022 15:19:29 +0100
Subject: [PATCH 2/2] substitutes: Log the failing queries.

* guix/substitutes.scm (%debug?): New variable.
(handle-narinfo-response): Log the failing queries if the %debug? parameter is
set.
---
guix/substitutes.scm | 15 +++++++++++++++
1 file changed, 15 insertions(+)

Toggle diff (35 lines)
diff --git a/guix/substitutes.scm b/guix/substitutes.scm
index 9014cf61ec..819eb2c73e 100644
--- a/guix/substitutes.scm
+++ b/guix/substitutes.scm
@@ -90,6 +90,12 @@ (define %narinfo-cache-directory
(string-append %state-directory "/substitute/cache"))
(string-append (cache-directory #:ensure? #f) "/substitute")))
+(define %debug?
+ ;; Enable debug mode by setting the GUIX_SUBSTITUTE_DEBUG environmnent
+ ;; variable.
+ (make-parameter
+ (getenv "GUIX_SUBSTITUTE_DEBUG")))
+
(define (narinfo-cache-file cache-url path)
"Return the name of the local file that contains an entry for PATH. The
entry is stored in a sub-directory specific to CACHE-URL."
@@ -224,6 +230,15 @@ (define (handle-narinfo-response request response port result)
(let* ((path (uri-path (request-uri request)))
(hash-part (basename
(string-drop-right path 8)))) ;drop ".narinfo"
+ ;; Log the failing queries and indicate if it failed because the
+ ;; narinfo is being baked.
+ (when (%debug?)
+ (let ((baking?
+ (assoc-ref (response-headers response) 'x-baking)))
+ (display
+ (format #f "could not fetch ~a~a ~a~a~%"
+ url path code
+ (if baking? " (baking)" "")))))
(if len
(get-bytevector-n port len)
(read-to-eof port))
--
2.38.1
L
L
Ludovic Courtès wrote on 6 Jan 2023 23:42
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87mt6vxp20.fsf@gnu.org
Hi Mathieu!

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (22 lines)
>>
>> Plausible explanations that come to mind:
>>
>> 1. ‘guix publish’ returning 404, but not due to baking. Instead the
>> .drv is simply not in store, hence 404.
>>
>> 2. Client timeout (‘guix publish’ fails to reply on time).
>>
>> 3. Cached 404 in nginx (though we’re not supposed to cache those I
>> think?), or timeout in nginx (again due to ‘guix publish’ being too
>> slow and ‘proxy_read_timeout’ is reached, currently 10s).
>
> I focused on https://ci.guix.gnu.org/build/308493/details which is
> similar to the one linked above. Some derivations are successfully
> substituted then, one is not and it aborts.
>
> This build stopped at 2022/12/24 00:25:38 CET. At that time the nginx error
> log on Berlin looks like:
>
> 2022/12/24 00:25:23 [info] 128755#0: *178076209 recv() failed (104: Connection reset by peer) while sending to client, client: 78.X.Y.Z, server: ci.guix.gnu.org, request: "GET /x3c2f9zzxhk0ci81nrdsxzglp4b1h3di.narinfo HTTP/1.1", upstream: "http://127.0.0.1:3000/x3c2f9zzxhk0ci81nrdsxzglp4b1h3di.narinfo", host: "ci.guix.gnu.org"

It means that upstream (i.e., ‘guix publish’) closed the connection,
right?

And it means that it closed it prematurely I guess?

Toggle quote (5 lines)
> However, like suggested in your hypothesis number 1, it seems instead
> that we are replying 404 to the worker which resets the connection. As
> we have put aside the baking thing, the question is now why are those
> derivations not available?

In that case we’re not replying at all, are we?

Toggle quote (14 lines)
> From 9f9c839937ac2edd1b5901b2262c4be0954fa20c Mon Sep 17 00:00:00 2001
> From: Mathieu Othacehe <othacehe@gnu.org>
> Date: Wed, 28 Dec 2022 15:12:46 +0100
> Subject: [PATCH 1/2] scripts: publish: Add a custom baking header.
>
> Log the not-found responses and their reason (baking or not) to stdout. Also
> send the X-Baking custom header so that the client can be informed of the
> cause of the failure.
>
> * guix/scripts/publish.scm (not-found): Add a baking? argument to add the
> X-Baking HTTP header to the response if baking is in progress. Also, log the
> 404 responses to stdout, indicating if it is due to baking or not.
> (render-narinfo/cached): Pass the baking? argument.

[...]

Toggle quote (9 lines)
> (define* (not-found request
> - #:key (phrase "Resource not found")
> + #:key
> + baking?
> + (phrase "Resource not found")
> ttl)
> "Render 404 response for REQUEST."
> + (format #t (G_ "? ~a ~a: 404~a~%")

Drop ‘G_’ (we don’t translate debugging messages) and use ASCII, to be
on the safe side…

Toggle quote (9 lines)
> From 25ffc57864dbf34ca58741f89c1f790dbde6702f Mon Sep 17 00:00:00 2001
> From: Mathieu Othacehe <othacehe@gnu.org>
> Date: Wed, 28 Dec 2022 15:19:29 +0100
> Subject: [PATCH 2/2] substitutes: Log the failing queries.
>
> * guix/substitutes.scm (%debug?): New variable.
> (handle-narinfo-response): Log the failing queries if the %debug? parameter is
> set.

[...]

Toggle quote (6 lines)
> +(define %debug?
> + ;; Enable debug mode by setting the GUIX_SUBSTITUTE_DEBUG environmnent
> + ;; variable.
> + (make-parameter
> + (getenv "GUIX_SUBSTITUTE_DEBUG")))

Instead of an env. var., maybe add a ‘--debug’ command-line option and
parameterize ‘%debug?’ accordingly?

You can also have something like:

(define-syntax (debug fmt args ...)
(when (%debug?)
(format #t fmt args ...)))

LGTM with changes along these lines!

Thanks,
Ludo’.
M
M
Mathieu Othacehe wrote on 7 Jan 2023 14:40
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87358mo43k.fsf@gnu.org
Hello,

Toggle quote (5 lines)
> It means that upstream (i.e., ‘guix publish’) closed the connection,
> right?
>
> And it means that it closed it prematurely I guess?

Looks like it yes.

Toggle quote (7 lines)
>> However, like suggested in your hypothesis number 1, it seems instead
>> that we are replying 404 to the worker which resets the connection. As
>> we have put aside the baking thing, the question is now why are those
>> derivations not available?
>
> In that case we’re not replying at all, are we?

Well could be, I'm not 100% sure how to understand those nginx logs. If
we are replying anything, it will be visible with the new traces. If on
the other hand the publish server is hanging up then they won't help
much I guess.

Toggle quote (3 lines)
> Drop ‘G_’ (we don’t translate debugging messages) and use ASCII, to be
> on the safe side…

Done.

Toggle quote (3 lines)
> Instead of an env. var., maybe add a ‘--debug’ command-line option and
> parameterize ‘%debug?’ accordingly?

The --debug command-line feels better but it involves a guix-daemon
modification so I kept the environment variable,

Toggle quote (7 lines)
> You can also have something like:
>
> (define-syntax (debug fmt args ...)
> (when (%debug?)
> (format #t fmt args ...)))
>

and used that macro :)

Thanks for having a look!

Mathieu
L
L
Ludovic Courtès wrote on 9 Jan 2023 10:39
(name . Mathieu Othacehe)(address . othacehe@gnu.org)(address . 48468@debbugs.gnu.org)
87pmbot5at.fsf@gnu.org
Hi,

Mathieu Othacehe <othacehe@gnu.org> skribis:

Toggle quote (6 lines)
>> Instead of an env. var., maybe add a ‘--debug’ command-line option and
>> parameterize ‘%debug?’ accordingly?
>
> The --debug command-line feels better but it involves a guix-daemon
> modification so I kept the environment variable,

Oh sorry, I was confusing ‘substitute’ and ‘publish’, that makes sense!

Ludo’.
M
M
Mathieu Othacehe wrote on 10 Jan 2023 09:10
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 48468@debbugs.gnu.org)
87h6wyolmx.fsf@gnu.org
Hey,

So the debug mechanism is in place. Requesting a non-existing derivation
on a worker gives:

Toggle snippet (7 lines)
mathieu@hydra-guix-104 ~$ guix build /gnu/store/yd1p7069rs4xbbfwj5p7nzp9psw7d3vv-hello-2.12.1.drv
substitute: could not fetch http://141.80.167.131/yd1p7069rs4xbbfwj5p7nzp9psw7d3vv.narinfo 404
substitute: updating substitutes from 'http://141.80.167.131'... 100.0%
cannot build missing derivation ‘/gnu/store/yd1p7069rs4xbbfwj5p7nzp9psw7d3vv-hello-2.12.1.drv’
guix build: error: build of `/gnu/store/yd1p7069rs4xbbfwj5p7nzp9psw7d3vv-hello-2.12.1.drv' failed

as expected. The funny thing is that during the test failures of
tonight, none of those traces were displayed. That would mean that the
failure is not caused by a missing narinfo.

I added the "--debug" option to the guix-daemon on the workers as well
hoping to gather more info.

Thanks,

Mathieu
?
Your comment

Commenting via the web interface is currently disabled.

To comment on this conversation send an email to 48468@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 48468
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch