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

Done

Details

3 participants

Ludovic Courtès
Ludovic Courtès
Christopher Baines

Owner: unassigned

Submitted by: Ludovic Courtès

Severity: serious

Ludovic Courtès wrote on 15 Mar 2021 15:26

“Bad Read-Header-Line header: #<e of>” while substituting

Recipients:(address . bug-guix@gnu.org)

Message-ID:87eeggh4rh.fsf@inria.fr

As reported by a few people on IRC, ‘guix substitute’ sometimes fails in

a way that I just experienced (from

8154beffd8c121e953a7c4cd75c3eebfcc073a9a):

Toggle snippet (46 lines)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>

This is the kind of issue that ‘with-cached-connection’ as it can be

seen in 9158020d7853b6e7925802e0d0a082801c680e8f avoided:

Toggle snippet (23 lines)(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))))))

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

Ludo’.

Ludovic Courtès wrote on 15 Mar 2021 15:31

control message for bug #47157

Recipients:(address . control@debbugs.gnu.org)

Message-ID:87czw0h4j3.fsf@gnu.org

severity 47157 serious

quit

Christopher Baines wrote on 15 Mar 2021 18:02

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

Recipients:(name . Ludovic Courtès)(address . ludovic.courtes@inria.fr)(address . 47157@debbugs.gnu.org)

Message-ID:871rcgfiz9.fsf@cbaines.net

Ludovic Courtès <ludovic.courtes@inria.fr> writes:

Toggle quote (84 lines)> 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.

Christopher Baines wrote on 15 Mar 2021 20:53

Recipients:(address . 47157@debbugs.gnu.org)(name . Ludovic Courtès)(address . ludovic.courtes@inria.fr)

Message-ID:87v99sdwh9.fsf@cbaines.net

Christopher Baines <mail@cbaines.net> writes:

Toggle quote (102 lines)> 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.

ice-9/boot-9.scm:1669:16: In procedure raise-exception:

Wrong number of values returned to continuation (expected 2)

Ludovic Courtès wrote on 15 Mar 2021 21:30

Recipients:(name . Christopher Baines)(address . mail@cbaines.net)(address . 47157@debbugs.gnu.org)

Message-ID:87a6r4cg88.fsf@gnu.org

Christopher Baines <mail@cbaines.net> skribis:

Toggle quote (18 lines)>> 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 think that’s not enough because we can’t rely on the server’s state

intent here.

For example, you have a keep-alive connection that you keep in cache.

Minutes later, you come back and send a request over that port. If the

server dropped the connection in the meantime, that can manifest in any

of the ways we’ve seen: 'bad-response when attempting to read the

response, some 'gnutls-error, 'system-error and EPIPE, etc. There’s no

way to determine in advance whether the socket is fine.

That’s why the initial approach was to wrap all the call sites were the

socket was known to be possibly “tainted” in ‘with-cached-connection’.

Toggle quote (5 lines)

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

I believe in this case ‘port-closed?’ returns true because the
socket/TLS record port got closed right at the end of the response, so
it’s the “easy” case; I don’t think it captures the situation I
described above where an error comes up later while trying to write
to/read from the port.

Ludo’.

Christopher Baines wrote on 15 Mar 2021 21:37

Recipients:(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 47157@debbugs.gnu.org)

Message-ID:87sg4wdugg.fsf@cbaines.net

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

Toggle quote (44 lines)> Christopher Baines <mail@cbaines.net> skribis:
>
>>> 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 think that’s not enough because we can’t rely on the server’s state
> intent here.
>
> For example, you have a keep-alive connection that you keep in cache.
> Minutes later, you come back and send a request over that port.  If the
> server dropped the connection in the meantime, that can manifest in any
> of the ways we’ve seen: 'bad-response when attempting to read the
> response, some 'gnutls-error, 'system-error and EPIPE, etc.  There’s no
> way to determine in advance whether the socket is fine.
>
> That’s why the initial approach was to wrap all the call sites were the
> socket was known to be possibly “tainted” in ‘with-cached-connection’.
>
>> 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.
>
> I believe in this case ‘port-closed?’ returns true because the
> socket/TLS record port got closed right at the end of the response, so
> it’s the “easy” case; I don’t think it captures the situation I
> described above where an error comes up later while trying to write
> to/read from the port.

Yeah, of course, I think error handling is needed as well, it just

occurred to me when looking at this issue and the relevant code.

Ludovic Courtès wrote on 18 Mar 2021 17:04

Recipients:(name . Christopher Baines)(address . mail@cbaines.net)(address . 47157-done@debbugs.gnu.org)

Message-ID:8735wsmos2.fsf@gnu.org

This should now be fixed by c37e3b92ad0334ba2fe7ee4e98631f0a4edeee21.

Thanks, Chris!

Ludo’.

Closed

Your comment

This issue is archived.

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

To respond to this issue using the mumi CLI, first switch to it

mumi current 47157

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

is:open	open issues
is:done	closed issues
submitter:<who>	search issue submitter
author:<who>	search by message author
date:yesterday..now	search by issue date
mdate:3m..2d	search by message date