bug#47157: “Bad Read-Header-Line header: #<eof>” while substituting

[Christopher Baines]

Christopher Baines <mail@cbaines.net> writes:

> Ludovic Courtès <ludovic.courtes@inria.fr> writes:
>
>> As reported by a few people on IRC, ‘guix substitute’ sometimes fails in
>> a way that I just experienced (from
>> 8154beffd8c121e953a7c4cd75c3eebfcc073a9a):
>>
>> --8<---------------cut here---------------start------------->8---
>> downloading from 
>> https://ci.guix.gnu.org/nar/gzip/0bji0q5n59595xaqkqrp2gv52lbz55xz-libpng-1.6.37
>>  .
>>  libpng-1.6.37  275KiB                                 11.0MiB/s 00:00 
>> [##################] 100.0%
>>
>> downloading from 
>> https://ci.guix.gnu.org/nar/lzip/h3a5ygxxh4gakhnl53mq7z9b43l8z05g-python-minimal.
>>  python-minimal-wrapper-3.8.2  351B                     293KiB/s 00:00 
>> [##################] 100.0%
>>
>> downloading from 
>> https://ci.guix.gnu.org/nar/lzip/h8j09yb5d8dh3jffvpzawxslig9bwhdr-freetype-2.10..
>>  freetype-2.10.4  600KiB                                3.0MiB/s 00:00 
>> [##################] 100.0%
>>
>> building /gnu/store/2wfzazqz9g5xizi4vq4pv75nkh1m24bp-perl-5.30.2.drv...
>> Backtrace:
>> In guix/ui.scm:
>>   2164:12 19 (run-guix-command _ . _)
>> In guix/scripts/substitute.scm:
>>     691:2 18 (guix-substitute . _)
>> In unknown file:
>>           17 (with-continuation-barrier #<procedure thunk ()>)
>> In ice-9/boot-9.scm:
>>   1736:10 16 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
>> In unknown file:
>>           15 (apply-smob/0 #<thunk 7fcb3b3594a0>)
>> In ice-9/boot-9.scm:
>>   1736:10 14 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
>>   1736:10 13 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
>>   1731:15 12 (with-exception-handler #<procedure 7fcb3a7c4150 at 
>> ice-9/boot-9.scm:1815:7 (exn)> _)
>> In guix/scripts/substitute.scm:
>>    740:17 11 (_)
>>     434:7 10 (process-substitution _ 
>> "/gnu/store/ns00dyapjbq9037dwrxa7hc31dvir00n-grub-minimal-2.)
>> In ice-9/boot-9.scm:
>>   1736:10  9 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
>> In guix/scripts/substitute.scm:
>>     443:9  8 (_)
>> In ice-9/boot-9.scm:
>>   1731:15  7 (with-exception-handler #<procedure 7fcb3a7d37b0 at 
>> ice-9/boot-9.scm:1815:7 (exn)> _)
>>   1669:16  6 (raise-exception _ #:continuable? _)
>>   1667:16  5 (raise-exception _ #:continuable? _)
>>   1669:16  4 (raise-exception _ #:continuable? _)
>>   1764:13  3 (_ #<&compound-exception components: (#<&error> #<&irritants 
>> irritants: (read-header)
>>   1669:16  2 (raise-exception _ #:continuable? _)
>>   1667:16  1 (raise-exception _ #:continuable? _)
>>   1669:16  0 (raise-exception _ #:continuable? _)
>>
>> ice-9/boot-9.scm:1669:16: In procedure raise-exception:
>> Bad Read-Header-Line header: #<eof>
>> --8<---------------cut here---------------end--------------->8---
>>
>> This is the kind of issue that ‘with-cached-connection’ as it can be
>> seen in 9158020d7853b6e7925802e0d0a082801c680e8f avoided:
>>
>> --8<---------------cut here---------------start------------->8---
>> (define* (call-with-cached-connection uri proc
>>                                       #:optional
>>                                       (open-connection
>>                                        open-connection-for-uri/cached))
>>   (let ((port (open-connection uri)))
>>     (catch #t
>>       (lambda ()
>>         (proc port))
>>       (lambda (key . args)
>>         ;; If PORT was cached and the server closed the connection in the
>>         ;; meantime, we get EPIPE.  In that case, open a fresh connection 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.
>>         (if (or (and (eq? key 'system-error)
>>                      (= EPIPE (system-error-errno `(,key ,@args))))
>>                 (and (eq? key 'gnutls-error)
>>                      (eq? (first args) error/invalid-session))
>>                 (memq key '(bad-response bad-header bad-header-component)))
>>             (proc (open-connection uri #:fresh? #t))
>>             (apply throw key args))))))
>> --8<---------------cut here---------------end--------------->8---
>>
>> I think 7b812f7c84c43455cdd68a0e51b6ded018afcc8e and subsequent commits
>> may have caused this regression.  In particular, in
>> 20c08a8a45d0f137ead7c05e720456b2aea44402,
>> ‘call-with-connection-error-handling’ is now used, but that one doesn’t
>> catch the exceptions mentioned above, in this case ‘bad-header’.
>
> I think the behaviour changed unintentionally with [1], however,
> thinking about the connection reuse in process-substitution compared
> with http-multiple-get, there's no attempt here to look at if the server
> has specified whether the connection should be closed.
>
> 1: 
> https://git.savannah.gnu.org/cgit/guix.git/commit/?id=f50f5751fff4cfc6d5abba9681054569694b7a5c
>
> Just like http-multiple-get, it's probably worth trying to check the
> headers of the response, look at whether the server has indicated that
> the connection should be closed, and if so, close the connection,
> forcing a new one to be established for future requests.
>
> I haven't tested this theory, but maybe if that happened, then some
> occurrences of trying to read a response, and not being able to would be
> prevented.

I've now actually got around to testing this, I'm no expert at running
the substitute script manually without the guix-daemon, but I gave it a
go, using a local NGinx instance which just allowed two requests per
connection.

With these changes [2], connections were closed when appropriate and a
new one is established when the next nar is fetched.

2: https://issues.guix.gnu.org/47174

When testing using the same approach with master, I get this exception
[3], so either I'm doing something wrong, or this isn't a circumstance
under which there can be a bad-header issue. Regardless, I'm not sure
what's going on with this exception below.

3:
ice-9/boot-9.scm:1669:16: In procedure raise-exception:
Wrong number of values returned to continuation (expected 2)

signature.asc
Description: PGP signature