cabal-install update fails going through a HTTP proxy (but not consistently)

[acid2]

I have installed Cabal, cabal-install and HTTP all from source on my Arch Linux machine, which has GHC 6.10.3 installed. When running cabal update this will occasionally work, but most often fails with the error:

cabal: user error (Codec.Compression.Zlib: premature end of compressed stream)

In this case, inspecting ~/.cabal/packages/hackage.haskell.org/00-index.tar.gz shows a file size that varies around 1-15K, rather than the expected ~900K.

Attached are logs of cabal-update failing, and working:

Downloading the latest package list from hackage.haskell.org
Sending:
GET http://hackage.haskell.org/packages/archive/00-index.tar.gz HTTP/1.1
User-Agent: cabal-install/0.6.2
Host: hackage.haskell.org
proxy uri host: wwwcache.lancs.ac.uk, port: :8080
Creating new connection to wwwcache.lancs.ac.uk:8080
Received:
HTTP/1.0 200 OK
Date: Tue, 09 Jun 2009 13:50:46 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Tue, 09 Jun 2009 09:53:44 GMT
ETag: "3890c4-f8d7c-55909a00"
Accept-Ranges: bytes
Content-Length: 1019260
Content-Type: application/x-tar
Content-Encoding: x-gzip
Age: 854
X-Cache: HIT from wwwcache.lancs.ac.uk
X-Cache-Lookup: HIT from wwwcache.lancs.ac.uk:8080
X-Cache: MISS from wwwcache.lancs.ac.uk
X-Cache-Lookup: MISS from wwwcache.lancs.ac.uk:8080
Via: 1.0 wwwcache3.lancs.ac.uk:8080 (squid/2.6.STABLE22), 1.0
wwwcache1.lancs.ac.uk:8080 (squid/2.7.STABLE4)
Connection: close
Downloaded to /home/ollie/.cabal/packages/hackage.haskell.org/00-index.tar.gz

Downloading the latest package list from hackage.haskell.org
Sending:
GET http://hackage.haskell.org/packages/archive/00-index.tar.gz HTTP/1.1
User-Agent: cabal-install/0.6.2
Host: hackage.haskell.org
proxy uri host: wwwcache.lancs.ac.uk, port: :8080
Creating new connection to wwwcache.lancs.ac.uk:8080
Received:
HTTP/1.0 200 OK
Date: Tue, 09 Jun 2009 13:50:46 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Tue, 09 Jun 2009 09:53:44 GMT
ETag: "3890c4-f8d7c-55909a00"
Accept-Ranges: bytes
Content-Length: 1019260
Content-Type: application/x-tar
Content-Encoding: x-gzip
Age: 875
X-Cache: HIT from wwwcache.lancs.ac.uk
X-Cache-Lookup: HIT from wwwcache.lancs.ac.uk:8080
Via: 1.0 wwwcache3.lancs.ac.uk:8080 (squid/2.6.STABLE22)
Proxy-Connection: close
Downloaded to /home/ollie/.cabal/packages/hackage.haskell.org/00-index.tar.gz
Reading available packages...

I was also asked to try running wget in verbose mode, this is the output:

--2009-06-09 16:17:00--  http://hackage.haskell.org/packages/archive/00-index.tar.gz
Resolving wwwcache.lancs.ac.uk... 194.80.32.11, 194.80.32.8, 194.80.32.9, ...
Connecting to wwwcache.lancs.ac.uk|194.80.32.11|:8080... connected.
Proxy request sent, awaiting response... 
  HTTP/1.0 200 OK
  Date: Tue, 09 Jun 2009 13:50:46 GMT
  Server: Apache/2.2.3 (Debian)
  Last-Modified: Tue, 09 Jun 2009 09:53:44 GMT
  ETag: "3890c4-f8d7c-55909a00"
  Accept-Ranges: bytes
  Content-Length: 1019260
  Content-Type: application/x-tar
  Content-Encoding: x-gzip
  Age: 1558
  X-Cache: HIT from wwwcache.lancs.ac.uk
  X-Cache-Lookup: HIT from wwwcache.lancs.ac.uk:8080
  Via: 1.0 wwwcache3.lancs.ac.uk:8080 (squid/2.6.STABLE22)
  Proxy-Connection: close
Length: 1019260 (995K) [application/x-tar]
Saving to: `00-index.tar.gz.2'

100%[===================================================================================================>] 1,019,260   --.-K/s   in 0.09s   

2009-06-09 16:17:00 (11.1 MB/s) - `00-index.tar.gz.2' saved [1019260/1019260]

[duncan]

Difference:

In failing case

X-Cache: HIT from wwwcache.lancs.ac.uk
X-Cache-Lookup: HIT from wwwcache.lancs.ac.uk:8080
X-Cache: MISS from wwwcache.lancs.ac.uk
X-Cache-Lookup: MISS from wwwcache.lancs.ac.uk:8080
Via: 1.0 wwwcache3.lancs.ac.uk:8080 (squid/2.6.STABLE22), 1.0
wwwcache1.lancs.ac.uk:8080 (squid/2.7.STABLE4)
Connection: close

In the working case

X-Cache: HIT from wwwcache.lancs.ac.uk
X-Cache-Lookup: HIT from wwwcache.lancs.ac.uk:8080
Via: 1.0 wwwcache3.lancs.ac.uk:8080 (squid/2.6.STABLE22)
Proxy-Connection: close

In particular in the failing case we get a cache hit followed by a mystery miss and finally Connection: close. In the working case we get no miss and a Proxy-Connection: close.

Why Connection: vs Proxy-Connection: we wonder, and what is this cache miss about?

[acid2]

Just a quick update on this. If I change my http_proxy variable from wwwcache.lancs.ac.uk to wwwcache3.lancs.ac.uk, this problem doesn't happen. It seems that somewhere in the haskell code, something is tripping up by the fact that wwwcache.lancs.ac.uk is actually a round-robin dispatch (or something...) to other proxy servers.

[duncan]

Apparently acid2 was using HTTP-4000.0.7.

[rjohnson]

I have (what seems to be) the same or a similar problem. This is using the 2009.2.0.1 Haskell Platform installer on XP. In my case however, it doesn't seem to be related to a proxy server, as I'm not using one. Here is cabal's output:

cabal -v3 update
Downloading the latest package list from hackage.haskell.org
Sending:
GET /packages/archive/00-index.tar.gz HTTP/1.1
Host: hackage.haskell.org
User-Agent: cabal-install/0.6.2
Creating new connection to hackage.haskell.org
Received:
HTTP/1.0 200 OK
Date: Wed, 10 Jun 2009 15:06:07 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Wed, 10 Jun 2009 10:48:16 GMT
ETag: "3890c6-f9187-366ebc00"
Accept-Ranges: bytes
Content-Length: 1020295
Content-Type: application/x-tar
Content-Encoding: x-gzip
X-Cache: MISS from mds-swf1.mds.aw.loc
Via: 1.0 mds-swf1.mds.aw.loc:8080 (http_scan/4.0.2.6.19)
Connection: close
Downloaded to C:\Documents and Settings\Rjohnson\Application
Data\cabal\packages\hackage.haskell.org\00-index.tar.gz
cabal.exe: user error (Codec.Compression.Zlib: premature end of compressed stream)

and here is wget's output:

wget -dv http://hackage.haskell.org/packages/archive/00-index.tar.gz
Setting --verbose (verbose) to 1
DEBUG output created by Wget 1.11.4 on cygwin.

--2009-06-10 11:04:50--  http://hackage.haskell.org/packages/archive/00-index.tar.gz
Resolving hackage.haskell.org... 69.30.63.197
Caching hackage.haskell.org => 69.30.63.197
Connecting to hackage.haskell.org|69.30.63.197|:80... connected.
Created socket 3.
Releasing 0x00693ed8 (new refcount 1).

---request begin---
GET /packages/archive/00-index.tar.gz HTTP/1.0
User-Agent: Wget/1.11.4
Accept: */*
Host: hackage.haskell.org
Connection: Keep-Alive

---request end---
HTTP request sent, awaiting response...
---response begin---
HTTP/1.0 200 OK
Date: Wed, 10 Jun 2009 15:04:51 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Wed, 10 Jun 2009 10:48:16 GMT
ETag: "3890c6-f9187-366ebc00"
Accept-Ranges: bytes
Content-Length: 1020295
Content-Type: application/x-tar
Content-Encoding: x-gzip
X-Cache: MISS from mds-swf1.mds.aw.loc
Via: 1.0 mds-swf1.mds.aw.loc:8080 (http_scan/4.0.2.6.19)
Connection: keep-alive

---response end---
200 OK
Registered socket 3 for persistent reuse.
Length: 1020295 (996K) [application/x-tar]
Saving to: `00-index.tar.gz.1'

100%[======================================>] 1,020,295    144K/s   in 7.4s

2009-06-10 11:04:58 (135 KB/s) - `00-index.tar.gz.1' saved [1020295/1020295]

Note that wget also has the "X-Cache: MISS", but it doesn't appear to affect the download.

[duncan]

Note that it is using a proxy server, that's what these two lines are about:

X-Cache: MISS from mds-swf1.mds.aw.loc
Via: 1.0 mds-swf1.mds.aw.loc:8080 (http_scan/4.0.2.6.19)

It is however a transparent proxy, ie cabal itself is trying to connect directly to hackage.haskell.org but your network setup transparently redirects that to mds-swf1.mds.aw.loc:8080 which is an http proxy.

[duncan]

And here's another reported example of the same issue:

dever@carbon (~) -> cabal update -v3                                                                                                                 [17:41]
Downloading the latest package list from hackage.haskell.org
Sending:
GET /packages/archive/00-index.tar.gz HTTP/1.1
User-Agent: cabal-install/0.6.2
Host: hackage.haskell.org
proxy uri host: proxy.dcu.ie, port: :8080
Creating new connection to proxy.dcu.ie:8080
Received:
HTTP/1.1 200 OK
Date: Thu, 11 Jun 2009 16:41:54 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Thu, 11 Jun 2009 16:00:48 GMT
ETag: "58c20d-f9605-b1faec00"
Accept-Ranges: bytes
Content-Length: 1021445
Content-Type: application/x-tar
Content-Encoding: x-gzip
X-Cache: MISS from cache.dcu.ie
X-Cache-Lookup: MISS from cache.dcu.ie:3128
Via: 1.1 proxy1.dcu.ie:3128 (squid/2.7.STABLE4)
Connection: close
Downloaded to
/home/member/d/dever/.cabal/packages/hackage.haskell.org/00-index.tar.gz
cabal: user error (Codec.Compression.Zlib: premature end of compressed stream)

Now running again and getting a proxy cache hit:

dever@carbon (~) -> cabal update -v3                                                                                                                 [17:41]
Downloading the latest package list from hackage.haskell.org
Sending:
GET /packages/archive/00-index.tar.gz HTTP/1.1
User-Agent: cabal-install/0.6.2
Host: hackage.haskell.org
proxy uri host: proxy.dcu.ie, port: :8080
Creating new connection to proxy.dcu.ie:8080
Received:
HTTP/1.1 200 OK
Date: Thu, 11 Jun 2009 16:41:59 GMT
Server: Apache/2.2.3 (Debian)
Last-Modified: Thu, 11 Jun 2009 16:00:48 GMT
ETag: "58c20d-f9605-b1faec00"
Accept-Ranges: bytes
Content-Length: 1021445
Content-Type: application/x-tar
Content-Encoding: x-gzip
X-Cache: MISS from cache.dcu.ie
X-Cache-Lookup: HIT from cache.dcu.ie:3128
Proxy-Connection: close
Downloaded to
/home/member/d/dever/.cabal/packages/hackage.haskell.org/00-index.tar.gz
Reading available packages...

Why has this started cropping up all of a sudden? Never seen this before then 3 reports in as many days. Do we suspect HTTP-4000.0.6 -> 7 perhaps?

[michaeldever]

Extracting the tarball of the FileManip? package that was downloaded yeilds this:

/home/member/d/dever/.cabal/packages/hackage.haskell.org/00-index.tar.gz

gzip: stdin: unexpected end of file
FileManip-0.3.2/
FileManip-0.3.2/README
FileManip-0.3.2/FileManip.cabal
FileManip-0.3.2/System/
FileManip-0.3.2/System/FilePath/
FileManip-0.3.2/System/FilePath/GlobPattern.hs
tar: Unexpected EOF in archive
tar: Unexpected EOF in archive
tar: Error is not recoverable: exiting now

So it's definitely a problem with the HTTP package in my opinion. I'm not sure if it is a problem with the packages proxy handling, as it does download some of the package, but not all of it.

Seeing as both the Zlib library, and tar yield an end of stream error, its something that I'm reckoning is happening during transport.

[michaeldever]

 http://trac.haskell.org/http/ticket/8#comment:1

[vvv]

I have some news. First, there is a  proof of concept module manifesting this weird behaviour. Second, the problem seems to be caused by using Lazy.ByteString for HTTP response body (see getHTTP function in Distribution.Client.HttpUtils). Once it's replaced with strict ByteString, the [POC] module starts downloading complete files.

Please see my  comment to HTTP ticket#8 and consider replacing Lazy.ByteString's with strict ones where appropriate (HttpUtils.hs, Fetch.hs, ...?).

[vvv]

Replying to vvv:

Please see my  comment to HTTP ticket#8 and consider replacing Lazy.ByteString's with strict ones where appropriate (HttpUtils.hs, Fetch.hs, ...?).

Proxy servers return cached data. This is not good for our debugging purpose, and the  updated revision of POC module disables caching.

I still cannot fix cabal-install though. :-/

[vvv]

This small  patch fixes the problem. Please consider applying it.

[duncan]

I'd like to hear the opinion of the HTTP package maintainer on this issue since it sounds like a bug in the HTTP package. I would much prefer if possible to stick with using lazy bytestrings since it should let us save to disk in constant space.

[vvv]

Replying to duncan:

I'd like to hear the opinion of the HTTP package maintainer on this issue since it sounds like a bug in the HTTP package.

It does happen to be HTTP's bug. See  http://trac.haskell.org/http/ticket/8#comment:7.

[kosmikus]

By scanning the comments, it looks to me like this has most likely been an HTTP bug and has hopefully been fixed there. Therefore closing as "invalid" now.