Connection closed, retrying on Packages.bz2 files

[Josef Spillner]

Binary package hint: apt-proxy

This tool (the Karmic version) doesn't seem to get the caching of package information files right. When I run debootstrap over apt-proxy once, using ftp.de.debian.org as a backend, the directory /var/cache/apt-proxy/debian/dists/squeeze/main/binary-amd64 is used to cache Packages and Packages.bz2.

However, on subsequent calls, a combination of strange behaviour occurs. I've tested it by simply calling wget 'http://localhost:9999/debian/dists/squeeze/main/binary-amd64/Packages.bz2'.
* First of all, apt-proxy doesn't take the file from the cache, but instead tries to download it again.
* Second, it tries to download it twice, as can be confirmed with some ngrep logging:

####
T 192.168.0.8:55051 -> 141.76.2.4:80 [AP]
  GET /debian/dists/squeeze/main/binary-amd64/Packages.bz2 HTTP/1.0..host: ftp.de.debian.org....
###
T 192.168.0.8:55052 -> 141.76.2.4:80 [AP]
  GET /debian/dists/squeeze/main/binary-amd64/Packages.bz2 HTTP/1.0..host: ftp.de.debian.org....

* Third, one of the two streams seems to terminate, which might be a server-side policy. The manifestation of this issue on the user side looks as follows:

--2010-03-07 09:43:34-- http://localhost:9999/debian/dists/squeeze/main/binary-amd64/Packages.bz2
Resolving localhost... 127.0.0.1, ::1
Connecting to localhost|127.0.0.1|:9999... connected.
HTTP request sent, awaiting response... 200 Streaming file
Length: 6175863 (5.9M) [text/plain]
Saving to: `Packages.bz2'

 0% [ ] 4,041 --.-K/s in 0.01s

2010-03-07 09:43:34 (347 KB/s) - Connection closed at byte 4041. Retrying.

--2010-03-07 09:43:35-- (try: 2) http://localhost:9999/debian/dists/squeeze/main/binary-amd64/Packages.bz2

On the system side through apt-proxy.log, it looks as follows:

2010-03-07 09:43:34+0100 [TimeoutProtocol,client] [CacheEntry] download started:/var/cache/apt-proxy/debian/dists/squeeze/main/binary-amd64/Packages.bz2
2010-03-07 09:43:34+0100 [TimeoutProtocol,client] [CacheEntry] download started:/var/cache/apt-proxy/debian/dists/squeeze/main/binary-amd64/Packages
2010-03-07 09:43:34+0100 [TimeoutProtocol,client] [CacheEntry] download started:/var/cache/apt-proxy/debian/dists/squeeze/main/binary-amd64/Packages.bz2
2010-03-07 09:43:34+0100 [TimeoutProtocol,client] [CacheEntry] download started:/var/cache/apt-proxy/debian/dists/squeeze/main/binary-amd64/Packages
2010-03-07 09:43:34+0100 [TimeoutProtocol,client] Unhandled Error
        Traceback (most recent call last):
          File "/usr/lib/python2.6/dist-packages/twisted/python/log.py", line 84, in callWithLogger
            return callWithContext({"system": lp}, func, *args, **kw)
          File "/usr/lib/python2.6/dist-packages/twisted/python/log.py", line 69, in callWithContext
            return context.call({ILogContext: newCtx}, func, *args, **kw)
          File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 59, in callWithContext
            return self.currentContext().callWithContext(ctx, func, *args, **kw)
          File "/usr/lib/python2.6/dist-packages/twisted/python/context.py", line 37, in callWithContext
            return func(*args,**kw)
        --- <exception caught here> ---
          File "/usr/lib/python2.6/dist-packages/twisted/internet/selectreactor.py", line 146, in _doReadOrWrite
            why = getattr(selectable, method)()
          File "/usr/lib/python2.6/dist-packages/twisted/internet/tcp.py", line 463, in doRead
            return self.protocol.dataReceived(data)
          File "/usr/lib/python2.6/dist-packages/twisted/protocols/policies.py", line 444, in dataReceived
            ProtocolWrapper.dataReceived(self, data)
          File "/usr/lib/python2.6/dist-packages/twisted/protocols/policies.py", line 72, in dataReceived
            self.wrappedProtocol.dataReceived(data)
          File "/usr/lib/python2.6/dist-packages/twisted/protocols/basic.py", line 239, in dataReceived
            return self.rawDataReceived(data)
          File "/usr/lib/python2.6/dist-packages/apt_proxy/fetchers.py", line 399, in rawDataReceived
            self.fetcher.data_received(data)
          File "/usr/lib/python2.6/dist-packages/apt_proxy/fetchers.py", line 151, in data_received
            self.cacheEntry.download_data_received(data)
          File "/usr/lib/python2.6/dist-packages/apt_proxy/cache.py", line 389, in download_data_received
            req.write(data)
          File "/usr/lib/python2.6/dist-packages/apt_proxy/clients.py", line 278, in write
            uncompressed = self.uncompress(data)
          File "/usr/lib/python2.6/dist-packages/apt_proxy/clients.py", line 301, in uncompress
            return self.decompressor.decompress(data)
        exceptions.IOError: invalid data stream

In summary, I think there are two main issues here: The tool doesn't honour the fact that it cached the Packages.bz2 file just a few moments before the second call, and the tool tries to download the file twice.

[Josef Spillner (josefspillner)]

Another observation in combination with debootstrap: The Release file was taken from the cache, and therefore the size and MD5 sum of Packages.bz2 didn't match anymore as it changed on the server and was always retrieved from there. This causes debootstrap to fail. Looks like a direct effect of this bug.