Bug#316337: Here we are
>From traces/trace.2063 (helper/ftp)
(FYI, 0 and 1 are a pipe to the main apt process, 3 is a socket to the Debian FTP server).
read(0, "600 URI Acquire\nURI: ftp://ftp.debian.nl/debian/dists/stable/main/binary-i386/Packages.bz2\nFilename: /var/lib/apt/lists/partial/ftp.debian.nl_debian_dists_stable_main_binary-i386_Packages\nIndex-File: true\nLast-Modified: Tue, 18 Apr 2006 09:49:00 GMT\n\n", 64000) = 251
write(1, "102 Status\nURI: ftp://ftp.debian.nl/debian/dists/stable/main/binary-i386/Packages.bz2\nMessage: Query\n\n", 102) = 102
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "SIZE /debian/dists/stable/main/binary-i386/Packages.bz2\r\n", 57) = 57
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 987000})
read(3, "550 Could not get file size.\r\n", 10240) = 30
time([1146783584]) = 1146783584
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "MDTM /debian/dists/stable/main/binary-i386/Packages.bz2\r\n", 57) = 57
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 982000})
read(3, "213 20060430182400\r\n", 10240) = 20
stat64("/var/lib/apt/lists/partial/ftp.debian.nl_debian_dists_stable_main_binary-i386_Packages", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
write(1, "201 URI Done\nURI: ftp://ftp.debian.nl/debian/dists/stable/main/binary-i386/Packages.bz2\nFilename: /var/lib/apt/lists/partial/ftp.debian.nl_debian_dists_stable_main_binary-i386_Packages\nLast-Modified: Sun, 30 Apr 2006 18:24:00 GMT\n\n", 231) = 231
What happens here is that apt orders its helper to download stable/main/binary-i386/Packages.bz2 and put it into the associated partial file. The FTP helper first tries to get the file size, which fails. It then compares the modification time of the file on the server with the one of the (empty) partial file and decides not to download. It then tells apt that the download is complete (while really no download occured) and that the result can be found in the partial file. APT then thinks that this partial file is a .bz2 file which has to be decompressed, and feeds it through bunzip2, which screams in agony for receiving an empty file.
Now from traces/traces2/trace.2100:
read(0, "600 URI Acquire\nURI: ftp://security.debian.org/debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\nFilename: /var/lib/apt/lists/partial/security.debian.org_debian-security_dists_stable_updates_main_binary-i386_Packages\nIndex-File: true\nLast-Modified: Thu, 04 May 2006 08:07:21 GMT\n\n", 64000) = 297
write(1, "102 Status\nURI: ftp://security.debian.org/debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\nMessage: Query\n\n", 125) = 125
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "SIZE /debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\r\n", 74) = 74
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 870000})
read(3, "550 Could not get file size.\r\n", 10240) = 30
time([1146783730]) = 1146783730
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "MDTM /debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\r\n", 74) = 74
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 870000})
read(3, "213 20060504081019\r\n", 10240) = 20
stat64("/var/lib/apt/lists/partial/security.debian.org_debian-security_dists_stable_updates_main_binary-i386_Packages", 0xbfbde8dc) = -1 ENOENT (No such file or directory)
open("/var/lib/apt/lists/partial/security.debian.org_debian-security_dists_stable_updates_main_binary-i386_Packages", O_RDWR|O_CREAT, 0666) = 4
fcntl64(4, F_SETFD, FD_CLOEXEC) = 0
write(1, "200 URI Start\nURI: ftp://security.debian.org/debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\n\n";, 113) = 113
close(-1) = -1 EBADF (Bad file descriptor)
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "PASV\r\n", 6) = 6
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 865000})
read(3, "227 Entering Passive Mode (128,101,240,212,39,233)\r\n", 10240) = 52
socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 5
fcntl64(5, F_GETFL) = 0x2 (flags O_RDWR)
fcntl64(5, F_SETFL, O_RDWR|O_NONBLOCK) = 0
connect(5, {sa_family=AF_INET, sin_port=htons(10217), sin_addr=inet_addr("128.101.240.212")}, 16) = -1 EINPROGRESS (Operation now in progress)
select(6, NULL, [5], NULL, {120, 0}) = 1 (out [5], left {119, 871000})
getsockopt(5, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
ftruncate(4, 0) = 0
lseek(4, 0, SEEK_SET) = 0
select(4, NULL, [3], NULL, {120, 0}) = 1 (out [3], left {120, 0})
write(3, "RETR /debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\r\n", 74) = 74
select(4, [3], NULL, NULL, {120, 0}) = 1 (in [3], left {119, 868000})
read(3, "550 Failed to open file.\r\n", 10240) = 26
close(4) = 0
utime("/var/lib/apt/lists/partial/security.debian.org_debian-security_dists_stable_updates_main_binary-i386_Packages", [2006/05/04-10:10:19, 2006/05/04-10:10:19]) = 0
write(1, "400 URI Failure\nURI: ftp://security.debian.org/debian-security/dists/stable/updates/main/binary-i386/Packages.bz2\nMessage: Unable to fetch file, server said \'Failed to open file. \' [IP: 128.101.240.212 21]\n\n", 208) = 208
Here the same thing happens, but now the partial file doesn't exist, so the FTP helper decides to create the partial file and download. The download fails however, which is reported to apt. apt then decides to ignore the file, but doesn't delete the partial file.
This means that the problem is in the miscommunication between apt-get and helper/ftp. FTP reports a successful download while really no download occured at all, and when a download fails FTP reports a failure, but nobody thinks of deleting the partial file.
Reply to: