cannot fetch narinfo with HTTP pipelining

cannot fetch narinfo with HTTP pipelining

[Ricardo Wurmus]

Hi Guix,

I recently updated to CentOS 7.1, rebooted, fetched latest master (at
that time c267cc1578) and recompiled Guix (make clean-go && make clean
&& make).  On this machine I usually install Guix system-wide with `sudo
make install`.

I noticed that HTTP pipelining appears to be broken on this machine.
Whenever I ask Guix to do something that involves looking up narinfo
from Hydra for substitutes I get an error like this:

~~~~
[rwurmus@guix-builder:/localhome/rwurmus-tmp/guix] (542) $ guix package -r gcc-toolchain automake autoconf sqlite gettext libgcryptThe following packages will be removed:
   sqlite	3.8.7.4	/gnu/store/kl5cyra6x6jkavbxziwk55w8qx3qfy3x-sqlite-3.8.7.4
   libgcrypt	1.6.2	/gnu/store/wckky7fl5axa6pfp3mz5cla2rsmp4w2v-libgcrypt-1.6.2
   gettext	0.19.4	/gnu/store/5jhnjdx9sl4gl24dnb67ikx5p25m880y-gettext-0.19.4
   gcc-toolchain	4.9.2	/gnu/store/5wniqwf1l24dvrf9xq0l8lc71fqgms6g-gcc-toolchain-4.9.2
   automake	1.15	/gnu/store/i2b8d0yf33g3k8b2g8hzmjd455yj5maq-automake-1.15
   autoconf	2.69	/gnu/store/s8im76a70jcg81yrfjs6l3dfaivjfav6-autoconf-2.69

substitute: updating list of substitutes from 'http://hydra.gnu.org'...   0.0%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:  157: 18 [catch #t #<catch-closure 1447060> ...]
substitute: In unknown file:
substitute:    ?: 17 [apply-smob/1 #<catch-closure 1447060>]
substitute: In ice-9/boot-9.scm:
substitute:   63: 16 [call-with-prompt prompt0 ...]
substitute: In ice-9/eval.scm:
substitute:  432: 15 [eval # #]
substitute: In ice-9/boot-9.scm:
substitute: 2320: 14 [save-module-excursion #<procedure 147bd40 at ice-9/boot-9.scm:3961:3 ()>]
substitute: 3966: 13 [#<procedure 147bd40 at ice-9/boot-9.scm:3961:3 ()>]
substitute: 1645: 12 [%start-stack load-stack ...]
substitute: 1650: 11 [#<procedure 1479060 ()>]
substitute: In unknown file:
substitute:    ?: 10 [primitive-load "/usr/bin/guix"]
substitute: In guix/ui.scm:
substitute:  849: 9 [run-guix-command substitute "--query"]
substitute: In ice-9/boot-9.scm:
substitute:  157: 8 [catch getaddrinfo-error ...]
substitute:  157: 7 [catch srfi-34 #<procedure 1df9900 at guix/ui.scm:221:2 ()> ...]
substitute:  157: 6 [catch system-error ...]
substitute: In guix/scripts/substitute.scm:
substitute:  809: 5 [#<procedure 1df9920 at guix/scripts/substitute.scm:793:3 ()>]
substitute:  570: 4 [lookup-narinfos # #]
substitute:  539: 3 [fetch-narinfos # #]
substitute:  473: 2 [http-multiple-get "http://hydra.gnu.org" (# # #) ...]
substitute:  520: 1 [handle-narinfo-response # # ...]
substitute: In unknown file:
substitute:    ?: 0 [get-bytevector-n #<input: r6rs-custom-binary-input-port 1e07680> 15]
substitute: 
substitute: ERROR: In procedure get-bytevector-n:
substitute: ERROR: Throw to key `bad-response' with args `("EOF while reading response body: ~a bytes of ~a" (403 15))'.
guix package: error: build failed: substituter `substitute' died unexpectedly
~~~~

The numbers in the `bad-response' error message differ for different
operations.  In all cases the first number (here 403) is larger than the
second (here 15).  The second number is the reported content length.

Here's another one (with some additional debugging output) for installing
"glibc-locales":

~~~~
[rwurmus@guix-builder:/localhome/rwurmus-tmp/guix] (602) $ guix package -i glibc-locales
The following package will be installed:              
   glibc-locales	2.21	/gnu/store/cgwlkh0bz5swb4ahnnrdvcg951flvksg-glibc-locales-2.21

substitute: guix substitute: warning: REKADO: command: (--query)
substitute: guix substitute: warning: REKADO: command: have /gnu/store/13bmfr1zndvinf8bp3zw94l7a7bafm50-patch-2.7.4 /gnu/store/3rl9qzgdnmkdmi2s9fq1ci1sdf6vvgn2-profile /gnu/store/4b4l8mvnns7fy6hkhl14gacz5sr0b2ps-bash-light-4.3.33 /gnu/store/509xqn252vf2jcr79dm971m9g3fhb5hc-bison-2.7.1 /gnu/store/6x6q3idm8wwmmsixpc0a6bvkdw9lz3qi-bison-3.0.4 /gnu/store/7mb0vngvyarvjd0shiqjpks2sd87rhc3-flex-2.5.37 /gnu/store/829bkhjp870l8xx3x5h4njw7836hrcnj-bison-3.0.4.tar.xz /gnu/store/9i1ch9jf1rm1hxkzh865awg35mp4hhrg-bash-4.3.tar.xz /gnu/store/apcydvs2w5iz32iydmb8hlg2vhbzck5a-info-dir /gnu/store/cgwlkh0bz5swb4ahnnrdvcg951flvksg-glibc-locales-2.21 /gnu/store/ch0bxjzlrpf1mi2l97nnnhmil2173ga3-m4-1.4.17 /gnu/store/cn06rcfg2rvzlrrcvk4pnssmn51pqz0w-ed-1.10 /gnu/store/d5s4rpklyd93fdz8l4dvk8wz8v2fsssx-lzip-1.16 /gnu/store/d6ipki4d0zrfzqd7a03zbavs1gacbq1g-ca-certificate-bundle /gnu/store/jz06j5b1r12jw4p1qzchqvwwfyascy5p-glibc-2.21.tar.xz /gnu/store/kyrx7vynvzjlakhv7fnhvarhlhm1a06b-flex-2.5.37.tar.xz /gnu/store/n9z23dic151k507893wacb867sya9gxz-linux-libre-headers-3.3.8 /gnu/store/nj1hw38gz0rzhl30qac272dg8yhskayf-indent-2.2.10 /gnu/store/rrjkhp9jad7rghbaisyp18cp696gr4w1-glibc-2.21.tar.xz 
substitute: updating list of substitutes from 'http://hydra.gnu.org'...   0.0%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:  157: 19 [catch #t #<catch-closure 1b1f060> ...]
substitute: In unknown file:
substitute:    ?: 18 [apply-smob/1 #<catch-closure 1b1f060>]
substitute: In ice-9/boot-9.scm:
substitute:   63: 17 [call-with-prompt prompt0 ...]
substitute: In ice-9/eval.scm:
substitute:  432: 16 [eval # #]
substitute: In ice-9/boot-9.scm:
substitute: 2320: 15 [save-module-excursion #<procedure 1b53d40 at ice-9/boot-9.scm:3961:3 ()>]
substitute: 3966: 14 [#<procedure 1b53d40 at ice-9/boot-9.scm:3961:3 ()>]
substitute: 1645: 13 [%start-stack load-stack ...]
substitute: 1650: 12 [#<procedure 1b51060 ()>]
substitute: In unknown file:
substitute:    ?: 11 [primitive-load "/usr/bin/guix"]
substitute: In guix/ui.scm:
substitute:  849: 10 [run-guix-command substitute "--query"]
substitute: In ice-9/boot-9.scm:
substitute:  157: 9 [catch getaddrinfo-error ...]
substitute:  157: 8 [catch srfi-34 #<procedure 24d2720 at guix/ui.scm:221:2 ()> ...]
substitute:  157: 7 [catch system-error ...]
substitute: In guix/scripts/substitute.scm:
substitute:  812: 6 [#<procedure 24d2740 at guix/scripts/substitute.scm:793:3 ()>]
substitute:  570: 5 [lookup-narinfos # #]
substitute:  539: 4 [fetch-narinfos # #]
substitute:  473: 3 [http-multiple-get "http://hydra.gnu.org" (# # # ...) ...]
substitute:  512: 2 [handle-narinfo-response # # ...]
substitute:  312: 1 [read-narinfo #<input: r6rs-custom-binary-input-port 253bdd0> ...]
substitute: In unknown file:
substitute:    ?: 0 [get-bytevector-n #<input: r6rs-custom-binary-input-port 253bdd0> 3393]
substitute: 
substitute: ERROR: In procedure get-bytevector-n:
substitute: ERROR: Throw to key `bad-response' with args `("EOF while reading response body: ~a bytes of ~a" (4096 3393))'.
guix package: error: build failed: substituter `substitute' died unexpectedly
~~~~

Again, 3393 is the content length and 4096 is larger.

I then attached strace to guix-daemon with

  strace -s 345 -p $(pidof guix-daemon) -f -o log

which produced a 5MB log file.  The output around connecting to Hydra
and until the backtrace is printed follows:

~~~~
...
22371 munmap(0x7f5f54f47000, 4096)      = 0
22371 socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 12
22371 connect(12, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("XXX.XX.XX.XXX")}, 16) = 0
22371 poll([{fd=12, events=POLLOUT}], 1, 0) = 1 ([{fd=12, revents=POLLOUT}])
22371 sendmmsg(12, {{{msg_name(0)=NULL, msg_iov(1)=[{"[\207\1\0\0\1\0\0\0\0\0\0\5hydra\3gnu\3org\0\0\1\0\1", 31}], msg_controllen=0
, msg_flags=0}, 31}, {{msg_name(0)=NULL, msg_iov(1)=[{"J\234\1\0\0\1\0\0\0\0\0\0\5hydra\3gnu\3org\0\0\34\0\1", 31}], msg_controllen
=0, msg_flags=0}, 31}}, 2, MSG_NOSIGNAL) = 2
22371 poll([{fd=12, events=POLLIN}], 1, 5000) = 1 ([{fd=12, revents=POLLIN}])
22371 ioctl(12, FIONREAD, [76])         = 0
22371 recvfrom(12, "[\207\201\200\0\1\0\2\0\0\0\0\5hydra\3gnu\3org\0\0\1\0\1\300\f\0\5\0\1\0\0\1+\0\21\01620121227-hydra\300\22\300
+\0\1\0\1\0\0\1+\0\4\22\4Y.", 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("XXX.XX.XX.XXX")}, [16]) = 76
22371 poll([{fd=12, events=POLLIN}], 1, 4999) = 1 ([{fd=12, revents=POLLIN}])
22371 ioctl(12, FIONREAD, [111])        = 0
22371 recvfrom(12, "J\234\201\200\0\1\0\1\0\1\0\0\5hydra\3gnu\3org\0\0\34\0\1\300\f\0\5\0\1\0\0\1+\0\21\01620121227-hydra\300\22\30
0\22\0\6\0\1\0\0\3\203\0'\3ns1\300\22\nhostmaster\300\22x\v\255\10\0\0\16\20\0\0\0x\0\22u\0\0\0\16\20", 1972, 0, {sa_family=AF_INET
, sin_port=htons(53), sin_addr=inet_addr("XXX.XX.XX.XXX")}, [16]) = 111
22371 close(12)                         = 0
22371 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 12
22371 fcntl(12, F_GETFL)                = 0x2 (flags O_RDWR)
22371 lseek(12, 0, SEEK_CUR)            = -1 ESPIPE (Illegal seek)
22371 connect(12, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("18.4.89.46")}, 16) = 0
22371 fstat(12, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
22371 setsockopt(12, SOL_SOCKET, SO_RCVBUF, "\0000\0\0\4\0\0\0", 8) = 0
22371 setsockopt(12, SOL_SOCKET, SO_RCVBUF, "\0@\3\0\4\0\0\0", 8) = 0
22371 brk(0)                            = 0x2e2b000
22371 brk(0)                            = 0x2e2b000
22371 brk(0x2ff4000)                    = 0x2ff4000
22371 write(12, "GET /zr116bqryhn0snnjjcdgg87nmjvdjwlr.narinfo HTTP/1.1\r\nHost: hydra.gnu.org\r\n\r\nGET /z9har59cyizvjk6j4fv7049v
3hgikqgc.narinfo HTTP/1.1\r\nHost: hydra.gnu.org\r\n\r\nGET /z0ck7nw2c8la6jafl8mgvmfscdkvw810.narinfo HTTP/1.1\r\nHost: hydra.gnu.o
rg\r\n\r\nGET /ykczd220p5lx4g82anyavjmnzmxcjgzg.narinfo HTTP/1.1\r\nHost: hydra.gnu.org\r\n\r\nGET /y5ldcz6ddag8lpiibpfgi64y"..., 6
873) = 6873
22371 read(12, "HTTP/1.1 200 OK\r\nServer: nginx/1.6.2\r\nDate: Tue, 07 Apr 2015 09:14:08 GMT\r\nContent-Type: text/x-nix-narinfo\r
\nContent-Length: 4469\r\nConnection: keep-alive\r\n\r\n", 65536) = 157
22371 read(12, "StorePath: /gnu/store/zr116bqryhn0snnjjcdgg87nmjvdjwlr-icedtea6-1.13.6-jdk\nURL: nar/zr116bqryhn0snnjjcdgg87nmjvdjw
lr-icedtea6-1.13.6-jdk\nCompression: bzip2\nNarHash: sha256:0sw76yf3dx55r3llkpkdix6fbd7rp5iwsd5jbpvx7pb06nxfsnmq\nNarSize: 41467903
2\nReferences: 0867r7j93maxfyay8km1nrzhhg8dvdj1-giflib-4.2.3 3x89ffgn3g951szl7whzwc7w6g1bn6av-libxext-1."..., 65536) = 4344
22371 read(12, "NzQyRkRGMDRFODlCMDQ0NjBFM0U2QkM3MkU3RjFCNUZFQTVCMzA5MkZFRTU1MUEzQzQ0N0MxMkUxMDRFNjUjKQogICAoZSAjMDEwMDAxIykKICAgKQo
gICkKICkK\nHTTP/1.1 200 OK\r\nServer: nginx/1.6.2\r\nDate: Tue, 07 Apr 2015 09:14:08 GMT\r\nContent-Type: text/x-nix-narinfo\r\nCon
tent-Length: 3395\r\nConnection: keep-alive\r\n\r\nStorePath: /gnu/store/z9har59cyizvjk6j4fv7049v3hgikqgc-glib-2.4"..., 65536) = 72
40
22371 write(2, "updating list of substitutes from 'http://hydra.gnu.org'...   0.0%Backtrace:\n", 77) = 77
22369 <... select resumed> )            = 1 (in [14])
22369 read(14, "updating list of substitutes from 'http://hydra.gnu.org'...   0.0%Backtrace:\n", 4096) = 77
22369 write(4, "gmlo\0\0\0\0Y\0\0\0\0\0\0\0substitute: updating list of substitutes from 'http://hydra.gnu.org'...   0.0%Backtrace:
\n\0\0\0\0\0\0\0", 112) = 112
22369 select(15, [12 14], NULL, NULL, NULL <unfinished ...>
22371 write(2, "In ice-9/boot-9.scm:\n", 21) = 21
22369 <... select resumed> )            = 1 (in [14])
22369 read(14, "In ice-9/boot-9.scm:\n", 4096) = 21
22369 write(4, "gmlo\0\0\0\0!\0\0\0\0\0\0\0substitute: In ice-9/boot-9.scm:\n\0\0\0\0\0\0\0", 56) = 56
22369 select(15, [12 14], NULL, NULL, NULL <unfinished ...>
...
~~~~


I then tried to reproduce this on the REPL:

~~~~
scheme@(guile-user)> ,import (guix scripts substitute)  
scheme@(guile-user)> (guix-substitute "--query")

have /gnu/store/13bmfr1zndvinf8bp3zw94l7a7bafm50-patch-2.7.4 /gnu/store/4b4l8mvnns7fy6hkhl14gacz5sr0b2ps-bash-light-4.3.33 /gnu/store/509xqn252vf2jcr79dm971m9g3fhb5hc-bison-2.7.1 /gnu/store/6x6q3idm8wwmmsixpc0a6bvkdw9lz3qi-bison-3.0.4 /gnu/store/7mb0vngvyarvjd0shiqjpks2sd87rhc3-flex-2.5.37 /gnu/store/829bkhjp870l8xx3x5h4njw7836hrcnj-bison-3.0.4.tar.xz  /gnu/store/9i1ch9jf1rm1hxkzh865awg35mp4hhrg-bash-4.3.tar.xz /gnu/store/apcydvs2w5iz32iydmb8hlg2vhbzck5a-info-dir /gnu/store/cgwlkh0bz5swb4ahnnrdvcg951flvksg-glibc-locales-2.21 /gnu/store/ch0bxjzlrpf1mi2l97nnnhmil2173ga3-m4-1.4.17 /gnu/store/cn06rcfg2rvzlrrcvk4pnssmn51pqz0w-ed-1.10 /gnu/store/d5s4rpklyd93fdz8l4dvk8wz8v2fsssx-lzip-1.16 /gnu/store/d6ipki4d0zrfzqd7a03zbavs1gacbq1g-ca-certificate-bundle /gnu/store/jz06j5b1r12jw4p1qzchqvwwfyascy5p-glibc-2.21.tar.xz /gnu/store/kyrx7vynvzjlakhv7fnhvarhlhm1a06b-flex-2.5.37.tar.xz /gnu/store/n9z23dic151k507893wacb867sya9gxz-linux-libre-headers-3.3.8 /gnu/store/nj1hw38gz0rzhl30qac272dg8yhskayf-indent-2.2.10 /gnu/store/rrjkhp9jad7rghbaisyp18cp696gr4w1-glibc-2.21.tar.xz

updating list of substitutes from 'http://hydra.gnu.org'...   0.0%ERROR: In procedure get-bytevector-n:
ERROR: Throw to key `bad-response' with args `("EOF while reading response body: ~a bytes of ~a" (4096 3393))'.

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(guile-user) [1]> ,q
~~~~

However, I don't get any error for each of the individual paths:

~~~~
scheme@(guile-user)> ,import (guix scripts substitute)
scheme@(guile-user)> (guix-substitute "--query")

have /gnu/store/cn06rcfg2rvzlrrcvk4pnssmn51pqz0w-ed-1.10
updating list of substitutes from 'http://hydra.gnu.org'... 100.0%
/gnu/store/cn06rcfg2rvzlrrcvk4pnssmn51pqz0w-ed-1.10

have /gnu/store/d5s4rpklyd93fdz8l4dvk8wz8v2fsssx-lzip-1.16
updating list of substitutes from 'http://hydra.gnu.org'... 100.0%
/gnu/store/d5s4rpklyd93fdz8l4dvk8wz8v2fsssx-lzip-1.16
...
~~~~

In particular, it's the evaluation of (fetch-narinfo cache paths) that
fails:

~~~~
scheme@(guile-user)> ,module (guix scripts substitute)
scheme@(guix scripts substitute)> (define c (force (open-cache* %cache-url)))
scheme@(guix scripts substitute)> (fetch-narinfos cf '("/gnu/store/13bmfr1zndvinf8bp3zw94l7a7bafm50-patch-2.7.4" "/gnu/store/4b4l8mvnns7fy6hkhl14gacz5sr0b2ps-bash-light-4.3.33" "/gnu/store/509xqn252vf2jcr79dm971m9g3fhb5hc-bison-2.7.1" "/gnu/store/6x6q3idm8wwmmsixpc0a6bvkdw9lz3qi-bison-3.0.4" "/gnu/store/7mb0vngvyarvjd0shiqjpks2sd87rhc3-flex-2.5.37" "/gnu/store/829bkhjp870l8xx3x5h4njw7836hrcnj-bison-3.0.4.tar.xz" "/gnu/store/9i1ch9jf1rm1hxkzh865awg35mp4hhrg-bash-4.3.tar.xz" "/gnu/store/apcydvs2w5iz32iydmb8hlg2vhbzck5a-info-dir" "/gnu/store/cgwlkh0bz5swb4ahnnrdvcg951flvksg-glibc-locales-2.21" "/gnu/store/ch0bxjzlrpf1mi2l97nnnhmil2173ga3-m4-1.4.17" "/gnu/store/cn06rcfg2rvzlrrcvk4pnssmn51pqz0w-ed-1.10" "/gnu/store/d5s4rpklyd93fdz8l4dvk8wz8v2fsssx-lzip-1.16" "/gnu/store/d6ipki4d0zrfzqd7a03zbavs1gacbq1g-ca-certificate-bundle" "/gnu/store/jz06j5b1r12jw4p1qzchqvwwfyascy5p-glibc-2.21.tar.xz" "/gnu/store/kyrx7vynvzjlakhv7fnhvarhlhm1a06b-flex-2.5.37.tar.xz" "/gnu/store/n9z23dic151k507893wacb867sya9gxz-linux-libre-headers-3.3.8" "/gnu/store/nj1hw38gz0rzhl30qac272dg8yhskayf-indent-2.2.10" "/gnu/store/rrjkhp9jad7rghbaisyp18cp696gr4w1-glibc-2.21.tar.xz"))
updating list of substitutes from 'http://hydra.gnu.org'...   0.0%ERROR: In procedure get-bytevector-n:
ERROR: Throw to key `bad-response' with args `("EOF while reading response body: ~a bytes of ~a" (4096 3553))'.

Entering a new prompt.  Type `,bt' for a backtrace or `,q' to continue.
scheme@(guix scripts substitute) [1]> ,bt #:full? #t
In /localhome/rwurmus-tmp/guix/guix/scripts/substitute.scm:
   539:14  4 (fetch-narinfos #<<cache> url: "http://hydra.gnu.org" …> …)
     Local variables:
     $8 = cache = #<<cache> url: "http://hydra.gnu.org" store-director…>
     $9 = paths = ("/gnu/store/13bmfr1zndvinf8bp3zw94l7a7bafm50-pat…" …)
     $10 = url (boxed) = "http://hydra.gnu.org"
     $11 = update-progress! (boxed) = #<procedure 29988a0 at //localho…>
     $12 = handle-narinfo-response = #<procedure handle-narinfo-respon…>
     $13 = uri = #<<uri> scheme: http userinfo: #f host: "hydra.gnu.or…>
     $14 = key = http
     $15 = requests = (#<<request> method: GET uri: #<<uri> scheme:…> …)
     $16 = result = #<undefined>
   473:28  3 (http-multiple-get "http://hydra.gnu.org" (#<<reque…> …) …)
     Local variables:
     $17 = base-url = "http://hydra.gnu.org"
     $18 = requests = (#<<request> method: GET uri: #<<uri> scheme:…> …)
     $19 = proc = #<procedure handle-narinfo-response (request respons…>
     $20 = requests = (#<<request> method: GET uri: #<<uri> scheme:…> …)
     $21 = result = ()
     $22 = p = #<input-output: socket 11>
     $23 = requests = (#<<request> method: GET uri: #<<uri> scheme:…> …)
     $24 = result = ()
     $25 = w = #<<request> method: GET uri: #<<uri> scheme: http useri…>
     $26 = x = (#<<request> method: GET uri: #<<uri> scheme: http u…> …)
     $27 = resp = #<<response> version: (1 . 1) code: 200 reason-phras…>
     $28 = body = #<input: r6rs-custom-binary-input-port 2bf51a0>
     $29 = v = (connection keep-alive)
     $30 = w = connection
     $31 = x = (keep-alive)
     $32 = w = keep-alive
    512:9  2 (handle-narinfo-response #<<request> method: GET uri: …> …)
     Local variables:
     $33 = request = #<<request> method: GET uri: #<<uri> scheme: http…>
     $34 = response = #<<response> version: (1 . 1) code: 200 reason-p…>
     $35 = port = #<input: r6rs-custom-binary-input-port 2bf51a0>
     $36 = len = 3553
     $37 = key = 200
     $38 = narinfo = #<undefined>
   312:31  1 (read-narinfo #<input: r6rs-custom-binary-input-port 2…> …)
     Local variables:
     $39 = port = #<input: r6rs-custom-binary-input-port 2bf51a0>
     $40 = url = "http://hydra.gnu.org"
     $41 = size = 3553
In unknown file:
           0 (get-bytevector-n #<input: r6rs-custom-binary-input-po…> …)
     No local variables.
~~~~

I don't know how HTTP pipelining works; looking at the code of
guix/scripts/substitute.scm it seems that all responses should appear on
the same port in sequential order.  `handle-narinfo-response` lets
`read-narinfo` read the reported number of characters from the port.
The error message suggests that the responses are chunked (4096 is a
pretty number) and `read-narinfo` encounters the end of the chunk while
reading at least the second(?) response, but I'm just guessing here.

FWIW, I don't see these problems on a recent Fedora 21 workstation.

~~ Ricardo

Re: cannot fetch narinfo with HTTP pipelining

[Ludovic Courtès]

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

Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:

> The numbers in the `bad-response' error message differ for different
> operations.  In all cases the first number (here 403) is larger than the
> second (here 15).  The second number is the reported content length.

That rings a bell.

Could you try this patch?


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 2205 bytes --]

diff --git a/guix/http-client.scm b/guix/http-client.scm
index 051fcee..abd9e64 100644
--- a/guix/http-client.scm
+++ b/guix/http-client.scm
@@ -135,6 +135,47 @@ closed it will also close PORT, unless the KEEP-ALIVE? is true."
  (when (module-variable %web-http 'read-chunk-body)
    (module-set! %web-http 'make-chunked-input-port make-chunked-input-port))
 
+ (define (make-delimited-input-port port len keep-alive?)
+   "Return an input port that reads from PORT, and makes sure that
+exactly LEN bytes are available from PORT.  Closing the returned port
+closes PORT, unless KEEP-ALIVE? is true."
+   (define bytes-read 0)
+
+   (define (fail)
+     ((@@ (web response) bad-response)
+      "EOF while reading response body: ~a bytes of ~a"
+      bytes-read len))
+
+   (define (read! bv start count)
+     ;; Read at most LEN bytes in total.  HTTP/1.1 doesn't say what to do
+     ;; when a server provides more than the Content-Length, but it seems
+     ;; wise to just stop reading at LEN.
+     (let ((count (min count (- len bytes-read))))
+       (let loop ((ret (get-bytevector-n! port bv start count)))
+         (cond ((eof-object? ret)
+                (if (= bytes-read len)
+                    0                              ; EOF
+                    (fail)))
+               ((and (zero? ret) (> count 0))
+                ;; Do not return zero since zero means EOF, so try again.
+                (loop (get-bytevector-n! port bv start count)))
+               (else
+                (set! bytes-read (+ bytes-read ret))
+                ret)))))
+
+   (define close
+     (and (not keep-alive?)
+          (lambda ()
+            (close port))))
+
+   (make-custom-binary-input-port "delimited input port" read! #f #f close))
+
+ (unless (guile-version>? "2.0.9")
+   ;; Guile <= 2.0.9 had a bug whereby 'response-body-port' would read more
+   ;; than what 'content-length' says.  See Guile commit 802a25b.
+   (module-set! (resolve-interface '(web response))
+                'make-delimited-input-port make-delimited-input-port))
+
  (define (read-response-body* r)
    "Reads the response body from @var{r}, as a bytevector.  Returns
  @code{#f} if there was no response body."

[-- Attachment #3: Type: text/plain, Size: 108 bytes --]


Anyone using Guile < 2.0.11 is welcome to test this and report success
or failure!

Thanks,
Ludo’.

Re: cannot fetch narinfo with HTTP pipelining

[Ricardo Wurmus]

Ludovic Courtès writes:

> Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:
>
>> The numbers in the `bad-response' error message differ for different
>> operations.  In all cases the first number (here 403) is larger than the
>> second (here 15).  The second number is the reported content length.
>
> That rings a bell.
>
> Could you try this patch?

Thanks for the patch.  Unfortunately, guix fails to compile with the
patch applied:

~~~~~
[rwurmus@guix-builder:/localhome/rwurmus-tmp/guix] (621) $ make
make  all-recursive
make[1]: Entering directory `/localhome/rwurmus-tmp/guix'
Making all in po/guix
make[2]: Entering directory `/localhome/rwurmus-tmp/guix/po/guix'
make[2]: Leaving directory `/localhome/rwurmus-tmp/guix/po/guix'
Making all in po/packages
make[2]: Entering directory `/localhome/rwurmus-tmp/guix/po/packages'
make[2]: Leaving directory `/localhome/rwurmus-tmp/guix/po/packages'
make[2]: Entering directory `/localhome/rwurmus-tmp/guix'
/usr/bin/mkdir -p `dirname "guix/gnu-maintenance.go"` ;			\
unset GUILE_LOAD_COMPILED_PATH ;				\
LC_ALL=C							\
./pre-inst-env					\
/usr/bin/guild compile -L "." -L "."	\
  -Wformat -Wunbound-variable -Warity-mismatch			\
  --target="x86_64-unknown-linux-gnu"						\
  -o "guix/gnu-maintenance.go" "guix/gnu-maintenance.scm"
;;; note: source file ./guix/http-client.scm
;;;       newer than compiled /home/rwurmus/.cache/guile/ccache/2.0-LE-8-2.0/localhome/rwurmus-tmp/guix/guix/http-client.scm.go
Backtrace:
In system/base/compile.scm:
 216: 19 [read-and-compile #<input: guix/gnu-maintenance.scm 5> #:from ...]
 232: 18 [lp () #f #<module (#{ g114}#) ca1d80>]
 180: 17 [lp (#<procedure compile-tree-il (x e opts)>) (define-module # # ...) ...]
In ice-9/boot-9.scm:
2320: 16 [save-module-excursion #<procedure e509f0 at language/scheme/compile-tree-il.scm:29:3 ()>]
In language/scheme/compile-tree-il.scm:
  31: 15 [#<procedure e509f0 at language/scheme/compile-tree-il.scm:29:3 ()>]
In ice-9/psyntax.scm:
1091: 14 [expand-top-sequence ((define-module # # # ...)) () ((top)) ...]
 976: 13 [scan ((define-module (guix gnu-maintenance) #:use-module ...)) () ...]
 270: 12 [scan ((#(syntax-object let # ...) (#) (# #) ...)) () ...]
In ice-9/eval.scm:
 411: 11 [eval # ()]
In ice-9/boot-9.scm:
2870: 10 [define-module* (guix gnu-maintenance) #:filename ...]
2845: 9 [resolve-imports (((web uri)) ((web client)) ((web response)) ...)]
2783: 8 [resolve-interface (guix http-client) #:select ...]
2708: 7 [#<procedure 9a7440 at ice-9/boot-9.scm:2696:4 (name #:optional autoload version #:key ensure)> # ...]
2981: 6 [try-module-autoload (guix http-client) #f]
2320: 5 [save-module-excursion #<procedure fb3510 at ice-9/boot-9.scm:2982:17 ()>]
3001: 4 [#<procedure fb3510 at ice-9/boot-9.scm:2982:17 ()>]
In unknown file:
   ?: 3 [primitive-load-path "guix/http-client" ...]
In ice-9/eval.scm:
 432: 2 [eval # ()]
In unknown file:
   ?: 1 [scm-error misc-error #f ...]
In ice-9/boot-9.scm:
 106: 0 [#<procedure bde140 at ice-9/boot-9.scm:97:6 (thrown-k . args)> misc-error ...]

ice-9/boot-9.scm:106:20: In procedure #<procedure bde140 at ice-9/boot-9.scm:97:6 (thrown-k . args)>:
ice-9/boot-9.scm:106:20: No variable named make-delimited-input-port in #<interface (web response) f9bd80>
make[2]: *** [guix/gnu-maintenance.go] Error 1
make[2]: Leaving directory `/localhome/rwurmus-tmp/guix'
make[1]: *** [all-recursive] Error 1
make[1]: Leaving directory `/localhome/rwurmus-tmp/guix'
make: *** [all] Error 2
~~~~~


That's odd because:

~~~~~
[rwurmus@guix-builder:/localhome/rwurmus-tmp/guix] (631) $ guile
GNU Guile 2.0.9
Copyright (C) 1995-2013 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> ,module (web response)
scheme@(web response)> make-delimited-input-port
$1 = #<procedure make-delimited-input-port (port len keep-alive?)>
scheme@(web response)> 
~~~~~

The only difference from master is the applied patch.

~~ Ricardo

Re: cannot fetch narinfo with HTTP pipelining

[Ludovic Courtès]

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

Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:

> ice-9/boot-9.scm:106:20: In procedure #<procedure bde140 at ice-9/boot-9.scm:97:6 (thrown-k . args)>:
> ice-9/boot-9.scm:106:20: No variable named make-delimited-input-port in #<interface (web response) f9bd80>

Arf, that’s because I wrote ‘resolve-interface’ instead of
‘resolve-module’ (the former means “public interface”.)

New patch:


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: Type: text/x-patch, Size: 2202 bytes --]

diff --git a/guix/http-client.scm b/guix/http-client.scm
index 051fcee..3bffbb1 100644
--- a/guix/http-client.scm
+++ b/guix/http-client.scm
@@ -135,6 +135,47 @@ closed it will also close PORT, unless the KEEP-ALIVE? is true."
  (when (module-variable %web-http 'read-chunk-body)
    (module-set! %web-http 'make-chunked-input-port make-chunked-input-port))
 
+ (define (make-delimited-input-port port len keep-alive?)
+   "Return an input port that reads from PORT, and makes sure that
+exactly LEN bytes are available from PORT.  Closing the returned port
+closes PORT, unless KEEP-ALIVE? is true."
+   (define bytes-read 0)
+
+   (define (fail)
+     ((@@ (web response) bad-response)
+      "EOF while reading response body: ~a bytes of ~a"
+      bytes-read len))
+
+   (define (read! bv start count)
+     ;; Read at most LEN bytes in total.  HTTP/1.1 doesn't say what to do
+     ;; when a server provides more than the Content-Length, but it seems
+     ;; wise to just stop reading at LEN.
+     (let ((count (min count (- len bytes-read))))
+       (let loop ((ret (get-bytevector-n! port bv start count)))
+         (cond ((eof-object? ret)
+                (if (= bytes-read len)
+                    0                              ; EOF
+                    (fail)))
+               ((and (zero? ret) (> count 0))
+                ;; Do not return zero since zero means EOF, so try again.
+                (loop (get-bytevector-n! port bv start count)))
+               (else
+                (set! bytes-read (+ bytes-read ret))
+                ret)))))
+
+   (define close
+     (and (not keep-alive?)
+          (lambda ()
+            (close port))))
+
+   (make-custom-binary-input-port "delimited input port" read! #f #f close))
+
+ (unless (guile-version>? "2.0.9")
+   ;; Guile <= 2.0.9 had a bug whereby 'response-body-port' would read more
+   ;; than what 'content-length' says.  See Guile commit 802a25b.
+   (module-set! (resolve-module '(web response))
+                'make-delimited-input-port make-delimited-input-port))
+
  (define (read-response-body* r)
    "Reads the response body from @var{r}, as a bytevector.  Returns
  @code{#f} if there was no response body."

[-- Attachment #3: Type: text/plain, Size: 12 bytes --]


Ludo’.

Re: cannot fetch narinfo with HTTP pipelining

[Ricardo Wurmus]

Ludovic Courtès writes:

> Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:
>
>> ice-9/boot-9.scm:106:20: In procedure #<procedure bde140 at ice-9/boot-9.scm:97:6 (thrown-k . args)>:
>> ice-9/boot-9.scm:106:20: No variable named make-delimited-input-port in #<interface (web response) f9bd80>
>
> Arf, that’s because I wrote ‘resolve-interface’ instead of
> ‘resolve-module’ (the former means “public interface”.)
>
> New patch:

Thank you!  With this patch applied everything works as expected.  Yay!

~~ Ricardo

Re: cannot fetch narinfo with HTTP pipelining

[Ludovic Courtès]

Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:

> Ludovic Courtès writes:
>
>> Ricardo Wurmus <ricardo.wurmus@mdc-berlin.de> skribis:
>>
>>> ice-9/boot-9.scm:106:20: In procedure #<procedure bde140 at ice-9/boot-9.scm:97:6 (thrown-k . args)>:
>>> ice-9/boot-9.scm:106:20: No variable named make-delimited-input-port in #<interface (web response) f9bd80>
>>
>> Arf, that’s because I wrote ‘resolve-interface’ instead of
>> ‘resolve-module’ (the former means “public interface”.)
>>
>> New patch:
>
> Thank you!  With this patch applied everything works as expected.  Yay!

Great, pushed!

Ludo’.