I've investigated this bug, in apt-cacher 1.6.8, and believe I have found the problem.
First, here is a typical manifestation, from apt-get(8) downloading a slew of packages for the xubuntu-desktop metapackage: ----8<---- Get:600 http://midnight jaunty/main python-rdflib 2.4.0-5ubuntu1 [302kB] Get:601 http://midnight jaunty/main python-smbc 1.0.6-0ubuntu2 [15.9kB] Get:602 http://midnight jaunty/main unattended-upgrades 0.39 [13.2kB] Get:603 http://midnight jaunty/main python-software-properties 0.71.5 [24.4kB] Get:604 http://midnight jaunty/universe python-tunepimp 0.5.3-7ubuntu3 [19.9kB] Err http://midnight jaunty/main libpciaccess0 0.10.5-1 400 No Request Received Get:605 http://midnight jaunty/main radeontool 1.5+git76606164-0ubuntu2 [61.3kB] Get:606 http://midnight jaunty/main readahead 1:0.20050517.0220-1ubuntu5 [24.3kB] Get:607 http://midnight jaunty/main rss-glx 0.8.2-1ubuntu3 [3207kB] Get:608 http://midnight jaunty-updates/main samba-common 2:3.3.2-1ubuntu3.1 [4467kB] ---->8---- (This is the first such error in the download run; there were others.) During this run, I had apt-cacher's "debug" option enabled. I had also added a bit of code (which I'll present shortly) that logs exactly what gets read in by the sysread() call on line 1646. Below is an extract from the error.log file corresponding to the above. Notice the "sysread: >>......<<" lines, and in particular, look closely at the part where the request for libpciaccess0 is read in from the socket: ----8<---- Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: sysread: >>GET /ubuntu/pool/universe/libt/libtunepimp/python-tunepimp_0.5.3-7ubuntu3_all.deb HTTP/1.1<CRLF>Host: midnight:3142<CRLF>Connection: keep-alive<CRLF>User-Agent: Ubuntu APT-HTTP/1.3 (0.7.20.2ubuntu6)<CRLF><CRLF><< Thu Aug 13 23:17:07 2009|debug [32623]: got: GET /ubuntu/pool/universe/libt/libtunepimp/python-tunepimp_0.5.3-7ubuntu3_all.deb HTTP/1.1 Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: Host: midnight:3142 Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: Connection: keep-alive Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: User-Agent: Ubuntu APT-HTTP/1.3 (0.7.20.2ubuntu6) Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: Thu Aug 13 23:17:07 2009|debug [32623]: Resolved request is /ubuntu/pool/universe/libt/libtunepimp/python-tunepimp_0.5.3-7ubuntu3_all.deb Thu Aug 13 23:17:07 2009|debug [32623]: new base file: python-tunepimp_0.5.3-7ubuntu3_all.deb Thu Aug 13 23:17:07 2009|debug [32623]: looking for /srv/apt-cacher/packages/python-tunepimp_0.5.3-7ubuntu3_all.deb Thu Aug 13 23:17:07 2009|debug [32623]: Entering critical section : file download decision Thu Aug 13 23:17:07 2009|debug [32623]: HIT Thu Aug 13 23:17:07 2009|debug [32623]: Exiting critical section Thu Aug 13 23:17:07 2009|debug [32623]: checks done, can return now Thu Aug 13 23:17:07 2009|debug [32623]: Entering critical section : reading the header file Thu Aug 13 23:17:07 2009|debug [32623]: Exiting critical section Thu Aug 13 23:17:07 2009|debug [32623]: Header sent: HTTP/1.1 200 OK Connection: Keep-Alive Accept-Ranges: bytes ETag: "30bc02b-4da0-459320f9c9700" Content-Length: 19872 Content-Type: application/x-debian-package Last-Modified: Tue, 14 Oct 2008 08:04:12 GMT Thu Aug 13 23:17:07 2009|debug [32623]: ready to send contents of /srv/apt-cacher/packages/python-tunepimp_0.5.3-7ubuntu3_all.deb Thu Aug 13 23:17:07 2009|debug [32623]: read 19872 bytes Thu Aug 13 23:17:07 2009|debug [32623]: wrote 19872 (sum: 19872) bytes Thu Aug 13 23:17:07 2009|debug [32623]: read 0 bytes Thu Aug 13 23:17:07 2009|debug [32623]: fetcher released lock Thu Aug 13 23:17:07 2009|debug [32623]: read 0 bytes Thu Aug 13 23:17:07 2009|debug [32623]: Package sent Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: got: Thu Aug 13 23:17:07 2009|debug [32623]: Processing a new request line Thu Aug 13 23:17:07 2009|debug [32623]: sysread: >>GET /ubuntu/pool/main/libp/libpciaccess/libpciaccess0_0.10.5-1_amd64.de<< Thu Aug 13 23:17:07 2009|debug [32623]: Clean up before exiting. Thu Aug 13 23:17:10 2009|debug [32617]: Connection from 192.168.1.17 Thu Aug 13 23:17:10 2009|debug [32624]: New Daemon connection Thu Aug 13 23:17:10 2009|debug [32624]: Processing a new request line Thu Aug 13 23:17:10 2009|debug [32624]: sysread: >>GET /ubuntu/pool/main/r/radeontool/radeontool_1.5+git76606164-0ubuntu2_amd64.deb HTTP/1.1<CRLF>Host: midnight:3142<CRLF>Connection: keep-alive<CRLF>User-Agent: Ubuntu APT-HTTP/1.3 (0.7.20.2ubuntu6)<CRLF><CRLF><< Thu Aug 13 23:17:10 2009|debug [32624]: got: GET /ubuntu/pool/main/r/radeontool/radeontool_1.5+git76606164-0ubuntu2_amd64.deb HTTP/1.1 Thu Aug 13 23:17:10 2009|debug [32624]: Processing a new request line Thu Aug 13 23:17:10 2009|debug [32624]: got: Host: midnight:3142 Thu Aug 13 23:17:10 2009|debug [32624]: Processing a new request line Thu Aug 13 23:17:10 2009|debug [32624]: got: Connection: keep-alive Thu Aug 13 23:17:10 2009|debug [32624]: Processing a new request line Thu Aug 13 23:17:10 2009|debug [32624]: got: User-Agent: Ubuntu APT-HTTP/1.3 (0.7.20.2ubuntu6) ---->8---- The GET line is incomplete! For whatever reason (packet boundaries?) the request transmission got broken up right after the "e" in ".deb". (Note that the request was not *truncated*; if you do another sysread() at this point, you get the rest of it in.) The problem is that getRequestLine() doesn't handle this condition properly. Oh, sure, it knows what to do if it reads one or more complete lines plus a partial one; the partial bit goes into $reqTail and that gets prepended to the next sysread() chunk, and the first complete line is returned. But if it reads in *only a partial line*, then what? The partial bit goes into $reqTail, @reqLineBuf remains empty, and then--- line 1664---you shift a line off an *empty line buffer*. FAIL! And so handle_connection() never saw the request for libpciaccess0. All it got was an empty line, after which it bailed out and dropped the connection. What getRequestLine() needs to do is loop back and do another sysread() until it has at least one full line in the line-buffer to return. Here are my modifications, including the bit of code I used to monitor sysread(): --- /usr/share/apt-cacher/apt-cacher 2009-08-10 22:20:05.000000000 -0400 +++ apt-cacher 2009-08-14 00:57:13.000000000 -0400 @@ -1641,10 +1641,14 @@ push(@reqLineBuf, "GET $cgi_path", '', undef); # undef stops operation undef $cgi_path; # don't re-add it } - if(!...@reqlinebuf) { + while (!...@reqlinebuf) { # Fill buffer if (my $ret=sysread($source, my $buf, 1024)) { +my $buf2 = $buf; +$buf2 =~ s/\r\n/<CRLF>/g; +debug_message("sysread: >>$buf2<<\n"); + $buf=$reqTail.$buf if(defined($reqTail)); undef $reqTail; @@ -1656,9 +1660,13 @@ if(substr($buf, -2) ne "\r\n") { $reqTail=pop(@reqLineBuf); } + else { + pop(@reqLineBuf); + } } else { info_message "Warning: Read failed: $!" if !defined $ret && $source->error; + last; } } return shift(@reqLineBuf); The extra pop(@reqLineBuf) is there to take care of an annoying side effect of the preceding split() call: if $buf does end with "\r\n", then @reqLineBuf is going to have an empty line pushed onto the end. (This tweak has the beneficial side effect of eliminating the blank line often seen before GET lines in error.log with debugging enabled.) -- To UNSUBSCRIBE, email to debian-bugs-dist-requ...@lists.debian.org with a subject of "unsubscribe". Trouble? Contact listmas...@lists.debian.org
