Connection reuse for substitutes breaks with gzip

  • Done
  • quality assurance status badge
Details
3 participants
  • Léo Le Bouter
  • Ludovic Courtès
  • Bonface Munyoki K.
Owner
unassigned
Submitted by
Ludovic Courtès
Severity
important
Merged with
L
L
Ludovic Courtès wrote on 6 Mar 2021 15:47
(address . bug-guix@gnu.org)
878s70ibke.fsf@inria.fr
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:

Toggle snippet (68 lines)
$ ./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’.
L
L
Ludovic Courtès wrote on 9 Mar 2021 12:05
control message for bug #46967
(address . control@debbugs.gnu.org)
87a6rca8p9.fsf@gnu.org
severity 46967 important
quit
L
L
Ludovic Courtès wrote on 9 Mar 2021 12:07
Re: bug#46967: Connection reuse for substitutes breaks with gzip
(address . 46967@debbugs.gnu.org)
8735x4a8m8.fsf@gnu.org
Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (4 lines)
> 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:

Toggle snippet (32 lines)
$ ./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: ì½


Ludo’.
(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))
L
L
Ludovic Courtès wrote on 9 Mar 2021 14:13
(address . 46967@debbugs.gnu.org)
87r1ko8o7v.fsf@gnu.org
Even simpler:

Toggle snippet (39 lines)
$ ./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

(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))
L
L
Léo Le Bouter wrote on 10 Mar 2021 02:28
Connection reuse for substitutes breaks with gzip
(address . 46967@debbugs.gnu.org)
7a9c7364e8d1d5262dc3dfcd922bb537d9ca4b7f.camel@zaclys.net
I am also affected by this issue (non-deterministically) it seems.
Requires me to run 'guix system reconfigure ..' several times for
things to work.
-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEFIvLi9gL+xax3g6RRaix6GvNEKYFAmBIINcACgkQRaix6GvN
EKYaHA//UJZ2zKzed5xBPd20IiJRuugBx8P9k/1TyxlaNFFLAZKu7ms03IE4KPIJ
z0h6f/MbzCh7Je5lucZliW0zKBzBMgBsOA/px+QapCBiHHQIVqYnqY4WVg26Gr5s
mgliLYEWLZ/dCf6bKqh50R8rtfVyMaoOFPihYpApFH7GPr9SNzkALamJfiUa1Sm0
RonDielTpMavcG8Ziw5CgvfrkazoAtt5fGum99X8eCrKMIHKfnlpymL+F/S58YK0
7bsTNKKz2q1qk9jhfVBxbrNgMzwEYpN4SXQH/psQOsPpSmcJY4snyIlyUyaBArYg
Sy2VpijXVjC3KZ4YNJLGRoTmc9FCLWHrhc4Df3dwdH7RR4bg5sTBJSaKpF9uXx3/
SqOifxYPyckBn+WriTVRzvIMW79j6YYNvThqZxTAHitZTqn9ia8eDNrql/UWLocr
cSW+hoQMi9NcAGTORsA5GVfA480rOJvcARtdV/0KNz2+itVXsFO2HHIvimOLQh8C
Zc0tzzXu76krRRm7IDvecmdFV4TZw4FNkVsItlcfbEh0khLmKx6+437mnEQ5D5K/
pP0bJXXZ8+MEUALbLcyC2Kq/wnkdP3XHD7gBQG1CUNmUuUKLjQ0kadT9t1eMOvAs
06qgva0GgJ5dTx7fbqr6mGndcfM7KgffBtIN6VzyIBGU/5gpI3U=
=F1+b
-----END PGP SIGNATURE-----


L
L
Ludovic Courtès wrote on 11 Mar 2021 09:26
(address . 46967@debbugs.gnu.org)
87eegmxfi5.fsf@gnu.org
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:

Toggle snippet (12 lines)
(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"...

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’.
L
L
Ludovic Courtès wrote on 12 Mar 2021 11:42
(address . 46967@debbugs.gnu.org)
87r1kkvekm.fsf@gnu.org
Hi!

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

Toggle quote (3 lines)
> 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):


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’.
L
L
Ludovic Courtès wrote on 12 Mar 2021 16:08
(address . 46967@debbugs.gnu.org)
87sg50tnni.fsf@gnu.org
Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (10 lines)
> 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’.
L
L
Ludovic Courtès wrote on 12 Mar 2021 16:39
control message for bug #46967
(address . control@debbugs.gnu.org)
87k0qcs7nr.fsf@gnu.org
merge 46967 47055
quit
L
L
Ludovic Courtès wrote on 14 Mar 2021 11:17
Re: bug#46967: Connection reuse for substitutes breaks with gzip
(address . 46967-done@debbugs.gnu.org)
87mtv6m44e.fsf@gnu.org
Ludovic Courtès <ludo@gnu.org> skribis:

Toggle quote (17 lines)
> 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’.
Closed
B
B
Bonface Munyoki K. wrote on 16 Mar 2021 19:34
(address . 46967@debbugs.gnu.org)(address . ludo@gnu.org)
86lfant0bm.fsf@bonfacemunyoki.com
Ludovic Courtès <ludo@gnu.org> writes:
Toggle quote (21 lines)
> 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:
--
Bonface M. K. D4F09EB110177E03C28E2FE1F5BBAE1E0392253F
Humble GNU Emacs User / Bearer of scheme-y parens
Curator: https://upbookclub.com / Twitter: @BonfaceKilz
-----BEGIN PGP SIGNATURE-----

iQJKBAEBCAA0FiEE1PCesRAXfgPCji/h9buuHgOSJT8FAmBQ+h8WHG1lQGJvbmZh
Y2VtdW55b2tpLmNvbQAKCRD1u64eA5IlP0MLD/9o/jhS4lrDVnxoPmkSoKBQoB+Y
YfFatnOReDIbtdutfttk9CqoLMmV86kEbKU1BQMeYGuCgUbO4WZdP40bnW+2w+V3
gPRyc6VLBxOMPpcgP7BVCInNAE+8TV5ZzMaINstxnp2Oe6qRNtiGoue33eBX7X1J
JssOLqLkrksMVzZpysWgS93g7x9woFmDFxTDAPoHE9iGfbnoDdmZQtg1a6a8AFhh
fMCMLMjtNGFEwBaeNzCk6dIbU91L+DXTBVzU3CMZAZhihISPLj2rNUTTg1EiHLL0
/k9uMxWYWcqIb5wgf8mVFNsSiFq9O+cfA86X2HFbGOgRtGqhNmY3JkZjX/xLYIoY
PZMP2Tt3BwCniHYf8EaSBVxcvTySBE6h5yAuUryAs80fPuR2JCA4UyGryBGgrnZI
wvSumGyQwNqS4SxnDvzIEEbUFS6XB02Vx/+WAS1IbJJDqQj+cgSh4lWfWk8Uk00e
w2XBM5JfiqsFNdazM+0ikEFpEisMpT+MsksJDBUpuuz3756xGlY1JawUPB2RBe1X
Bo5QXHO0/BHPtIdZUamRKstF1l0j6iJEoLzpwWqBAAsdm3TOacJWZpcQ3vjHjldq
tcxxN0qhhZkxKygu/NqPCcphmywI5BYiBreg8Wyfq7uA1fGJAUNFP0y+sITYKLem
c/gCm0+4WooI5lzIIg==
=OP13
-----END PGP SIGNATURE-----

L
L
Ludovic Courtès wrote on 18 Mar 2021 10:32
(name . Bonface Munyoki K.)(address . me@bonfacemunyoki.com)(address . 46967@debbugs.gnu.org)
87wnu4vmbt.fsf@gnu.org
Bonface Munyoki K. <me@bonfacemunyoki.com> skribis:

Toggle quote (27 lines)
> 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:

Toggle snippet (4 lines)
ice-9/boot-9.scm:1669:16: In procedure raise-exception:
Bad http-version header component: ¡_¨””8á—¯ñÿ

which is typical of this bug.

Ludo’.
?