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:

~~~~
address@hidden:/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":

~~~~
address@hidden:/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, "address@hidden", 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