Package: apt-cacher Version: 1.5.3 Severity: normal Symptoms ========
When I attempt to download a deb, apt-get hangs up and, after a long delay, fails.: ___________________________________________ # apt-get -d dist-upgrade # [snip] Get:1 http://debian.betterworld.us testing/main libnss-dev 2:1.7.12-1.2 [185kB] Err http://debian.betterworld.us testing/main libnss-dev 2:1.7.12-1.2 Connection timed out Get:2 http://debian.betterworld.us unstable/main libnss-dev 2:1.7.12-1.2 [185kB] Err http://debian.betterworld.us unstable/main libnss-dev 2:1.7.12-1.2 Connection timed out Failed to fetch http://debian.betterworld.us:3142/linux.csua.berkeley.edu/debian/pool/main/m/mozilla/libnss-dev_1.7.12-1.2_i386.deb Connection timed out E: Some files failed to download ------------------------------------------------------- Here is the corresponding part of apt-cacher's error.log (extra debugging enabled): --------------------------------------------------------- Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27963]: got: Tue Jun 13 08:05:53 2006|192.168.40.1|debug [1493]: Connection from 192.168.40.1 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [1493]: registred child process: 27981 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: New HTTP connection open Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: testing allowed_hosts Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: checking against 192.168.40.0/24 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: testing denied_hosts Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Client 192.168.40.1 passed access control rules Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: GET /linux.csua.berkeley.edu/debian/pool/main/m/mozilla/libnss-dev_1.7.12-1.2_i386.deb HTTP/1.1 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: Host: debian.betterworld.us:3142 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: Connection: keep-alive Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: Range: bytes=184319- Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: If-Range: Wed, 07 Jun 2006 18:47:22 GMT Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: User-Agent: Debian APT-HTTP/1.3 Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: got: Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: new filename with just basename: libnss-dev_1.7.12-1.2_i386.deb Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: looking for /usr/local/var/mirrors/apt-cacher/packages/libnss-dev_1.7.12-1.2_i386.deb Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Entering critical section : file download decission Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: HIT Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Exiting critical section Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: checks done, can return now Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Entering critical section : reading the header file Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Exiting critical section Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: Header sent: HTTP/1.1 200 OK Connection: Keep-Alive Accept-Ranges: bytes Content-Length: 184928 Content-Type: application/x-debian-package Last-Modified: Wed, 07 Jun 2006 18:47:22 GMT Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: ready to send contents of /usr/local/var/mirrors/apt-cacher/packages/libnss-dev_1.7.12-1.2_i386.deb Tue Jun 13 08:05:53 2006|192.168.40.1|debug [27981]: opening file first: /usr/local/var/mirrors/apt-cacher/packages/libnss-dev_1.7.12-1.2_i386.deb Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: read 65536 bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: wrote 65536 (sum: 65536) bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: read 65536 bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: wrote 65536 (sum: 131072) bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: read 53248 bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: wrote 53248 (sum: 184320) bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: read 0 bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: complete file found Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: read 0 bytes Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: Package sent Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: got: Tue Jun 13 08:05:54 2006|192.168.40.1|debug [27981]: Processing a new request line Tue Jun 13 08:07:54 2006|192.168.40.1|debug [27981]: got: -------------------------------------------------------------------------- (that occurred twice, presumably once for each attempt). Analysis ======== I believe the cause of this is that the main .deb file is truncated. Despite that, there is a .complete entry: --------------------------------------------------------------------------- # find . -name '*libnss-dev*' -ls 10021 184 -rw-r--r-- 1 www-data www-data 184916 Feb 19 02:42 ./packages/libnss-dev_1.7.12-1.1_i386.deb 19235 180 -rw-r--r-- 1 www-data www-data 184320 Jun 12 04:00 ./packages/libnss-dev_1.7.12-1.2_i386.deb 3384 0 lrwxrwxrwx 1 www-data root 61 Dec 29 18:23 ./packages/libnss-dev_1.7.8-1sarge3_i386.deb -> /var/cache/apt/archives/libnss-dev_2%3a1.7.8-1sarge3_i386.deb 10029 4 -rw-r--r-- 1 www-data www-data 410 Feb 19 02:42 ./headers/libnss-dev_1.7.12-1.1_i386.deb 19233 4 -rw-r--r-- 1 www-data www-data 467 Jun 12 04:00 ./headers/libnss-dev_1.7.12-1.2_i386.deb 3385 4 -rw-r--r-- 1 www-data root 299 Dec 29 18:23 ./headers/libnss-dev_1.7.8-1sarge3_i386.deb 10031 4 -rw-r--r-- 1 www-data www-data 82 Feb 19 02:42 ./private/libnss-dev_1.7.12-1.1_i386.deb.complete 3386 0 -rw-r--r-- 1 www-data root 0 Dec 29 18:23 ./private/libnss-dev_1.7.8-1sarge3_i386.deb.complete 19236 0 -rw-r--r-- 1 www-data www-data 0 Jun 12 04:00 ./private/libnss-dev_1.7.12-1.2_i386.deb.complete wheat:/usr/local/var/mirrors/apt-cacher# cat ./headers/libnss-dev_1.7.12-1.2_i386.deb HTTP/1.1 200 OK Connection: Keep-Alive Date: Mon, 12 Jun 2006 11:00:37 GMT Accept-Ranges: bytes ETag: "6ed8e-2d260-cc3ac280" Server: Apache/2.0.54 (Debian GNU/Linux) mod_python/3.1.3 Python/2.3.5 PHP/4.3.10-16 mod_ssl/2.0.54 OpenSSL/0.9.7e mod_perl/1.999.21 Perl/v5.8.4 Content-Length: 184928 Content-Type: application/x-debian-package Last-Modified: Wed, 07 Jun 2006 18:47:22 GMT Client-Peer: 169.229.49.36:80 Client-Response-Num: 1 Keep-Alive: timeout=15, max=100 wheat:/usr/local/var/mirrors/apt-cacher# cat ./headers/libnss-dev_1.7.12-1.1_i386.deb HTTP/1.1 200 OK Connection: Keep-Alive Date: Sun, 19 Feb 2006 10:42:25 GMT Accept-Ranges: bytes ETag: "1368059-2d254-e2a12980" Server: Apache/2.0.54 (Debian GNU/Linux) mod_python/3.1.3 Python/2.3.5 PHP/4.3.10-15 Content-Length: 184916 Content-Type: application/x-debian-package Last-Modified: Sun, 05 Feb 2006 21:32:38 GMT Client-Peer: 128.32.112.231:80 Client-Response-Num: 1 Keep-Alive: timeout=15, max=100 ----------------------------------------------------------------- libnss-dev_1.7.12-1.2 is slightly shorter than what was in the headers, while -1.1 is exactly the length shown in the headers. I believe this originally happened because the partition filled. Assuming the .complete files are flags for download complete, it seems they are being created before the download is actually complete (maybe something to do with buffering?). Desired Behavior ================ I would like to see apt-cacher automatically detect and correct this situation. In other words, it should notice that the packages/ file is too short, and attempt to download it again. Failing such automatic behavior, or failing the attempted re-download, it would be good if apt-cacher failed more noisily and informatively, e.g., by writing a message to syslog, daemon.log, or somewhere else appropriate. I don't know if it is reasonable to communicate error conditions directly to the apt client that is accessing apt-cacher; if it is, that would be good too. Work-Around =========== # rm ./private/libnss-dev_1.7.12-1.2_i386.deb.complete allowed the apt download to succeed. apt-cacher got the complete package. -- System Information: Debian Release: testing/unstable APT prefers testing APT policy: (990, 'testing'), (990, 'stable'), (50, 'unstable') Architecture: i386 (i686) Shell: /bin/sh linked to /bin/bash Kernel: Linux 2.4.27advncdfs Locale: LANG=en_US, LC_CTYPE=en_US (charmap=ISO-8859-1) Versions of packages apt-cacher depends on: ii bzip2 1.0.3-2 high-quality block-sorting file co ii libwww-perl 5.805-1 WWW client/server library for Perl ii perl 5.8.8-4 Larry Wall's Practical Extraction apt-cacher recommends no packages. -- no debconf information -- To UNSUBSCRIBE, email to [EMAIL PROTECTED] with a subject of "unsubscribe". Trouble? Contact [EMAIL PROTECTED]
