bug#46967: Connection reuse for substitutes breaks with gzip

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

Ludovic Courtès <ludo@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: \x1f\0\0\x03ì½

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

Ludo’.


[-- Attachment #2: the reproducer --]
[-- Type: text/plain, Size: 1160 bytes --]

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

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

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


[-- Attachment #2: reproducer --]
[-- Type: text/plain, Size: 980 bytes --]

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

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

Hi!

Ludovic Courtès <ludo@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’.

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

Ludovic Courtès <ludo@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’.

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

> Ludovic Courtès <ludo@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’.

bug#46967: Connection reuse for substitutes breaks with gzip

[Bonface Munyoki K.]

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

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

> Ludovic Courtès <ludo@gnu.org> skribis:
>
>> Ludovic Courtès <ludo@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

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

bug#46967: Connection reuse for substitutes breaks with gzip

[Ludovic Courtès]

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

> Ludovic Courtès <ludo@gnu.org> writes:
>
>> Ludovic Courtès <ludo@gnu.org> skribis:
>>
>>> Ludovic Courtès <ludo@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’.

bug#46967: Connection reuse for substitutes breaks with gzip

[Léo Le Bouter via Bug reports for GNU Guix]

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

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

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]