GNU bug report logs - #46967
Connection reuse for substitutes breaks with gzip

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 46967 in the body.
You can then email your comments to 46967 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: <bug-guix <at> gnu.org>
Subject: Connection reuse for substitutes breaks with gzip
Date: Sat, 06 Mar 2021 15:47:13 +0100

As of commit cdc688c5ee106b7ee2547e4abd74ab81d7702d3d, it seems that the
connection reuse code for substitutes breaks if you’re fetching gzip
substitutes.

I tweaked ‘narinfo-best-uri’ to always choose gzip, and here’s what I get:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guix build vigra inkscape eigen pt-scotch 
accepted connection from pid 20839, user ludo
69.6 MB will be downloaded:
   /gnu/store/si36xnajxjnx7v6ywd7qyhyv8ar9aymn-vigra-1.11.1
   /gnu/store/0fcjk788gj7k6gsf3zsx8j8lyw6w896b-inkscape-1.0.2
substituting /gnu/store/0fcjk788gj7k6gsf3zsx8j8lyw6w896b-inkscape-1.0.2...
downloading from https://ci.guix.gnu.org/nar/gzip/0fcjk788gj7k6gsf3zsx8j8lyw6w896b-inkscape-1.0.2 ...
 inkscape-1.0.2  38.6MiB                                                    16.8MiB/s 00:02 [##################] 100.0%

substituting /gnu/store/si36xnajxjnx7v6ywd7qyhyv8ar9aymn-vigra-1.11.1...
Backtrace:
In guix/ui.scm:
  2164:12 19 (run-guix-command _ . _)
In guix/scripts/substitute.scm:
    664: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 7fa67ce511c0>)
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 7fa67c302390 at ice-9/boot-9.scm:1815:7 (exn)> _ #:unwind? _ # _)
In guix/scripts/substitute.scm:
   713:17 11 (_)
    414:7 10 (process-substitution _ "/gnu/store/si36xnajxjnx7v6ywd7qyhyv8ar9aymn-vigra-1.11.1" #:cache-urls _ #:acl …)
In ice-9/boot-9.scm:
  1736:10  9 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In guix/scripts/substitute.scm:
    423:9  8 (_)
In ice-9/boot-9.scm:
  1731:15  7 (with-exception-handler #<procedure 7fa67c42edb0 at ice-9/boot-9.scm:1815:7 (exn)> _ #:unwind? _ # _)
  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: (http-version "_'$Àçv\x8b\x8f7…>)
  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 http-version header component: _'$Àçv‹7$H?

Backtrace:
In ice-9/boot-9.scm:
  1736:10  4 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In unknown file:
           3 (apply-smob/0 #<thunk 7fa67e9cb520>)
In ice-9/boot-9.scm:
    718:2  2 (call-with-prompt _ _ #<procedure default-prompt-handler (k proc)>)
In ice-9/eval.scm:
    619:8  1 (_ #(#(#<directory (guile-user) 7fa67e9cec80>)))
In guix/ui.scm:
  2164:12  0 (run-guix-command _ . _)

guix/ui.scm:2164:12: In procedure run-guix-command:
Bad http-version header component: _'$Àçv‹7$H?

substitution of /gnu/store/si36xnajxjnx7v6ywd7qyhyv8ar9aymn-vigra-1.11.1 failed
guix build: error: some substitutes for the outputs of derivation `/gnu/store/k32m5dcf31psvx66n95icxbvyimrjrk5-vigra-1.11.1.drv' failed (usually happens due to networking issues); try `--fallback' to build derivation from source 
$ wget -qO - https://ci.guix.gnu.org/nar/gzip/si36xnajxjnx7v6ywd7qyhyv8ar9aymn-vigra-1.11.1 | gunzip > /dev/null
$ echo $?
0--8<---------------cut here---------------end--------------->8---

Ludo’.

Message #10 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Tue, 09 Mar 2021 12:07:11 +0100

[Message part 1 (text/plain, inline)]

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

> As of commit cdc688c5ee106b7ee2547e4abd74ab81d7702d3d, it seems that the
> connection reuse code for substitutes breaks if you’re fetching gzip
> substitutes.

Here’s a simple reproducer that systematically fails after the first
download:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guile ~/src/guix-debugging/http-pipelining-gzip.scm

;;; (fetch 164664960)
Backtrace:
In ice-9/boot-9.scm:
  1736:10 11 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In unknown file:
          10 (apply-smob/0 #<thunk 7f9bf630c520>)
In ice-9/boot-9.scm:
    718:2  9 (call-with-prompt _ _ #<procedure default-prompt-handler (k proc)>)
In ice-9/eval.scm:
    619:8  8 (_ #(#(#<directory (guile-user) 7f9bf630fc80>)))
In ice-9/boot-9.scm:
   2806:4  7 (save-module-excursion _)
  4351:12  6 (_)
In /home/ludo/src/guix-debugging/http-pipelining-gzip.scm:
     18:4  5 (_)
In guix/http-client.scm:
   116:21  4 (http-fetch _ #:port _ #:text? _ #:buffered? _ #:open-connection _ #:keep-alive? _ # _ #:headers _ # _)
In web/client.scm:
   526:24  3 (http-request _ #:body _ #:verify-certificate? _ #:port _ #:method _ #:version _ #:keep-alive? _ # _ # …)
In web/response.scm:
   198:31  2 (read-response #<input-output: string 7f9bf36c6000>)
In web/http.scm:
  1194:12  1 (read-response-line _)
    252:2  0 (parse-http-version _ _ _)

web/http.scm:252:2: In procedure parse-http-version:
Bad http-version header component: ì½

--8<---------------cut here---------------end--------------->8---

Ludo’.

[http-pipelining-gzip.scm (text/plain, inline)]

(use-modules (guix http-client)
             ((guix build download) #:select (open-connection-for-uri))
             (guix utils)
             ((guix serialization) #:select (dump-port*))
             (web uri)
             (web request)
             (web response)
             (srfi srfi-1))

(define %base-url
  "https://ci.guix.gnu.org")

(define port
  (open-connection-for-uri (string->uri %base-url)))

(let loop ()
  (define-values (input size)
    (http-fetch (string->uri
                 "https://ci.guix.gnu.org/nar/gzip/0fcjk788gj7k6gsf3zsx8j8lyw6w896b-inkscape-1.0.2")
                #:port port
                #:text? #f
                #:open-connection open-connection-for-uri ;/cached
                #:keep-alive? #t
                #:buffered? #f))

  (define-values (decompressed pids)
    (decompressed-port 'gzip input))

  (setvbuf decompressed 'none)
  (call-with-output-file "/tmp/out"
    (lambda (output)
      (setvbuf output 'none)
      (dump-port* decompressed output
                  (pk 'fetch 164664960)))) ;size of compressed nar

  (unless (every (compose zero? cdr waitpid) pids)
    (error "decomp error"))

  (loop))

Message #13 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Tue, 09 Mar 2021 14:13:08 +0100

[Message part 1 (text/plain, inline)]

Even simpler:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env  guile ~/src/guix-debugging/http-pipelining-gzip.scm

;;; (port #<input-output: file 7fced4c20000>)

;;; (input #<input: file 7fced4c8ef50>)

;;; (drain "")

;;; (fetch 16397)

;;; (port #<input-output: file 7fced4c20000>)
Backtrace:
In ice-9/boot-9.scm:
  1736:10 11 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In unknown file:
          10 (apply-smob/0 #<thunk 7fced7866520>)
In ice-9/boot-9.scm:
    718:2  9 (call-with-prompt _ _ #<procedure default-prompt-handler (k proc)>)
In ice-9/eval.scm:
    619:8  8 (_ #(#(#<directory (guile-user) 7fced7869c80>)))
In ice-9/boot-9.scm:
   2806:4  7 (save-module-excursion _)
  4351:12  6 (_)
In /home/ludo/src/guix-debugging/http-pipelining-gzip.scm:
     18:4  5 (_)
In guix/http-client.scm:
   116:21  4 (http-fetch _ #:port _ #:text? _ #:buffered? _ #:open-connection _ #:keep-alive? _ # _ #:headers _ # _)
In web/client.scm:
   526:24  3 (http-request _ #:body _ #:verify-certificate? _ #:port _ #:method _ #:version _ #:keep-alive? _ # _ # …)
In web/response.scm:
   198:31  2 (read-response #<input-output: string 7fced4c20000>)
In web/http.scm:
  1194:12  1 (read-response-line _)
    252:2  0 (parse-http-version _ _ _)

web/http.scm:252:2: In procedure parse-http-version:
Bad http-version header component: <!DOCTYPE

--8<---------------cut here---------------end--------------->8---

[http-pipelining-gzip.scm (text/plain, inline)]

(use-modules (guix http-client)
             ((guix build download) #:select (open-connection-for-uri))
             (guix utils)
             ((guix serialization) #:select (dump-port*))
             (web uri)
             (web request)
             (web response)
             (srfi srfi-1))

(define %base-url
  "https://guix.gnu.org")

(define port
  (open-connection-for-uri (string->uri %base-url)))

(let loop ()
  (define-values (input size)
    (http-fetch (string->uri %base-url)
                #:port (pk 'port port)
                #:text? #f
                #:open-connection open-connection-for-uri ;/cached
                #:keep-alive? #t
                #:buffered? #f))

  (define-values (decompressed pids)
    (filtered-port '("/run/current-system/profile/bin/cat") (pk 'input input)))

  (dump-port* decompressed (%make-void-port "w")
              (pk 'fetch size))

  (unless (every (compose zero? cdr waitpid) pids)
    (error "decomp error"))

  (loop))

Message #16 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Léo Le Bouter <lle-bout <at> zaclys.net>
To: 46967 <at> debbugs.gnu.org
Subject: Connection reuse for substitutes breaks with gzip
Date: Wed, 10 Mar 2021 02:28:55 +0100

[Message part 1 (text/plain, inline)]

I am also affected by this issue (non-deterministically) it seems.
Requires me to run 'guix system reconfigure ..' several times for
things to work.

[signature.asc (application/pgp-signature, inline)]

Message #19 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Thu, 11 Mar 2021 09:26:42 +0100

Turns out GnuTLS has a buffer for the record layer attached to the
session.  After the first GET in the main process, it looks like this:

--8<---------------cut here---------------start------------->8---
(gdb) p session->internals.record_buffer
$9 = {head = 0x7f7370, tail = 0x7f7370, length = 1, byte_length = 16219}
(gdb) p *session->internals.record_buffer->head
$10 = {next = 0x0, prev = 0x0, mark = 165, msg = {
    data = 0x7f73c0 "HTTP/1.1 200 OK\r\nServer: nginx\r\nDate: Wed, 10 Mar 2021 21:23:44 GMT\r\nContent-Type: text/html\r\nContent-Length: 16397\r\nConnection: keep-alive\r\nAccept-Ranges: bytes\r\n\r\n<!DOCTYPE html><html lang=\"en\"><hea"..., size = 16384}, maximum_size = 18751, uhead_mark = 0, type = GNUTLS_APPLICATION_DATA, record_sequence = 1, 
  epoch = 0, htype = 72, handshake_sequence = 0}
(gdb) p *(&session->internals.record_buffer->head.msg.data[165])
$11 = 60 '<'
(gdb) p (&session->internals.record_buffer->head.msg.data[165])
$12 = (unsigned char *) 0x7f7465 "<!DOCTYPE html><html lang=\"en\"><head><title>GNU's advanced distro and transactional package manager — GNU Guix</title><meta charset=\"UTF-8\" /><meta name=\"keywords\" content=\"GNU, Linux, Unix, Free s"...
--8<---------------cut here---------------end--------------->8---

IOW, the main process hasn’t consumed the body of the HTTP response.

This is because with ‘filtered-port’, the input port is dumped from a
child process, not from the calling process.

To be continued…

Ludo’.

Message #22 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Fri, 12 Mar 2021 11:42:01 +0100

Hi!

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

> This is because with ‘filtered-port’, the input port is dumped from a
> child process, not from the calling process.

I decided to take a heavy-handed solution to that problem, which is to
augment Guile-zlib with an interface for gzip compression/decompression
not restricted to file ports (‘call-with-gzip-output-port’ & co. are
restricted to file ports):

  https://notabug.org/guile-zlib/guile-zlib/commit/b899ac2fecf91475da1eba7e7b24708ea8b5fb73

That way, we can change ‘decompressed-port’ in (guix utils) to perform
in-process decompression for ‘gzip’, like it does for zstd and lzip.

If everything goes well, I’ll cut a Guile-zlib release today and update
Guix accordingly.

Ludo’.

Message #25 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Fri, 12 Mar 2021 16:08:49 +0100

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

> I decided to take a heavy-handed solution to that problem, which is to
> augment Guile-zlib with an interface for gzip compression/decompression
> not restricted to file ports (‘call-with-gzip-output-port’ & co. are
> restricted to file ports):
>
>   https://notabug.org/guile-zlib/guile-zlib/commit/b899ac2fecf91475da1eba7e7b24708ea8b5fb73
>
> That way, we can change ‘decompressed-port’ in (guix utils) to perform
> in-process decompression for ‘gzip’, like it does for zstd and lzip.

Done in a04aef2430645357d7796969d4b6453478ff8a3f!

I’ll update the ‘guix’ package so people on Guix System can get the fix,
and then we can close this bug.

Ludo’.

Message #32 received at 46967-done <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: 46967-done <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Sun, 14 Mar 2021 11:17:05 +0100

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

> Ludovic Courtès <ludo <at> gnu.org> skribis:
>
>> I decided to take a heavy-handed solution to that problem, which is to
>> augment Guile-zlib with an interface for gzip compression/decompression
>> not restricted to file ports (‘call-with-gzip-output-port’ & co. are
>> restricted to file ports):
>>
>>   https://notabug.org/guile-zlib/guile-zlib/commit/b899ac2fecf91475da1eba7e7b24708ea8b5fb73
>>
>> That way, we can change ‘decompressed-port’ in (guix utils) to perform
>> in-process decompression for ‘gzip’, like it does for zstd and lzip.
>
> Done in a04aef2430645357d7796969d4b6453478ff8a3f!
>
> I’ll update the ‘guix’ package so people on Guix System can get the fix,
> and then we can close this bug.

Done in 8154beffd8c121e953a7c4cd75c3eebfcc073a9a, closing!

Ludo’.

Message #40 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Bonface Munyoki K. <me <at> bonfacemunyoki.com>
To: 46967 <at> debbugs.gnu.org
Cc: ludo <at> gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Tue, 16 Mar 2021 21:34:05 +0300

[Message part 1 (text/plain, inline)]

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

> Ludovic Courtès <ludo <at> gnu.org> skribis:
>
>> Ludovic Courtès <ludo <at> gnu.org> skribis:
>>
>>> I decided to take a heavy-handed solution to that problem, which is to
>>> augment Guile-zlib with an interface for gzip compression/decompression
>>> not restricted to file ports (‘call-with-gzip-output-port’ & co. are
>>> restricted to file ports):
>>>
>>>   https://notabug.org/guile-zlib/guile-zlib/commit/b899ac2fecf91475da1eba7e7b24708ea8b5fb73
>>>
>>> That way, we can change ‘decompressed-port’ in (guix utils) to perform
>>> in-process decompression for ‘gzip’, like it does for zstd and lzip.
>>
>> Done in a04aef2430645357d7796969d4b6453478ff8a3f!
>>
>> I’ll update the ‘guix’ package so people on Guix System can get the fix,
>> and then we can close this bug.
>
> Done in 8154beffd8c121e953a7c4cd75c3eebfcc073a9a, closing!
>

Very far fetched but could this be the cause of:
https://lists.gnu.org/archive/html/help-guix/2021-03/msg00052.html?

-- 
Bonface M. K. D4F09EB110177E03C28E2FE1F5BBAE1E0392253F
Humble GNU Emacs User / Bearer of scheme-y parens
Curator: <https://upbookclub.com> / Twitter: @BonfaceKilz

[signature.asc (application/pgp-signature, inline)]

Message #43 received at 46967 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Bonface Munyoki K. <me <at> bonfacemunyoki.com>
Cc: 46967 <at> debbugs.gnu.org
Subject: Re: bug#46967: Connection reuse for substitutes breaks with gzip
Date: Thu, 18 Mar 2021 10:32:38 +0100

Bonface Munyoki K. <me <at> bonfacemunyoki.com> skribis:

> Ludovic Courtès <ludo <at> gnu.org> writes:
>
>> Ludovic Courtès <ludo <at> gnu.org> skribis:
>>
>>> Ludovic Courtès <ludo <at> gnu.org> skribis:
>>>
>>>> I decided to take a heavy-handed solution to that problem, which is to
>>>> augment Guile-zlib with an interface for gzip compression/decompression
>>>> not restricted to file ports (‘call-with-gzip-output-port’ & co. are
>>>> restricted to file ports):
>>>>
>>>>   https://notabug.org/guile-zlib/guile-zlib/commit/b899ac2fecf91475da1eba7e7b24708ea8b5fb73
>>>>
>>>> That way, we can change ‘decompressed-port’ in (guix utils) to perform
>>>> in-process decompression for ‘gzip’, like it does for zstd and lzip.
>>>
>>> Done in a04aef2430645357d7796969d4b6453478ff8a3f!
>>>
>>> I’ll update the ‘guix’ package so people on Guix System can get the fix,
>>> and then we can close this bug.
>>
>> Done in 8154beffd8c121e953a7c4cd75c3eebfcc073a9a, closing!
>>
>
> Very far fetched but could this be the cause of:
> https://lists.gnu.org/archive/html/help-guix/2021-03/msg00052.html?

Yes; their log shows:

--8<---------------cut here---------------start------------->8---
ice-9/boot-9.scm:1669:16: In procedure raise-exception:
Bad http-version header component: ¡_¨””8ᗯñÿ
--8<---------------cut here---------------end--------------->8---

which is typical of this bug.

Ludo’.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.