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

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

[Ludovic Courtès]

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

Ludo’.

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

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 5253 bytes --]


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.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]

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

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 6200 bytes --]


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)

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]

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

[Ludovic Courtès]

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.

Ludo’.

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

[Christopher Baines]

[-- Attachment #1: Type: text/plain, Size: 2498 bytes --]


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

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

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 987 bytes --]

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

[Ludovic Courtès]

This should now be fixed by c37e3b92ad0334ba2fe7ee4e98631f0a4edeee21.

Thanks, Chris!

Ludo’.