bug#48468: substitute server connection timeout

[Ludovic Courtès]

Hi Mathieu!

Mathieu Othacehe <othacehe@gnu.org> skribis:

>> (From <https://ci.guix.gnu.org/build/224849/log/raw>.)
>>
>> 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?

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

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

[...]

>  (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…

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

[...]

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