While trying to create a fresh Debian system, using apt-cacher as a proxy for ftp.us.debian.org, I got a GPG error. Since this is an official archive, and since there aren't the usual blizzard or requests, the debug log of apt-cacher is much easier to see. It is attached. I notice some "read 0" messages, but they seem to occur even with the successful handling of the Release file. Otherwise, everything seems in order. The gpg file does exist in apt-cacher's cache, with the indicated size (189). It reads -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux)
iD8DBQBHRzRypw2vU2Bw06ERAhCIAJ93kaKghERSLYbcHb/Q2eAarahAugCcCLlK E414JGwmGjAfW3r1mKuDKWU= =jMl4 -----END PGP SIGNATURE----- The error on the installation machine is gpgv: Signature made Fri Nov 23 20:13:38 2007 UTC using DSA key ID 6070D3A1 gpgv: BAD signature from "Debian Archive Automatic Signing Key (4.0/etch) <[EMAIL PROTECTED]>" [manual transcription] I ran this on the machine with apt-cacher (except lines have been wrapped): corn:/var/cache/apt-cacher/packages# gpg --verify ftp.us.debian.org_debian_dists_lenny_Release.gpg ftp.us.debian.org_debian_dists_lenny_Release gpg: Signature made Fri 23 Nov 2007 12:13:38 PM PST using DSA key ID 6070D3A1 gpg: BAD signature from "Debian Archive Automatic Signing Key (4.0/etch) <[EMAIL PROTECTED]>" When I get the relevant files from the site via a browser, the gpg file matches but the Release file is completely different (and verifies correctly against the gpg signature). The files in my cache both have timestamps matching the time of download. I see why you asked about the cache. I suppose I could have caught the remote archive in mid-update; the signature was made only about half an hour before I did my fetch. But this seems to be happening quite frequently, and only with apt-cacher, for that to be the whole story. Ross
Fri Nov 23 12:53:17 2007|192.168.40.44|debug [3826]: Connection from 192.168.40.44 Fri Nov 23 12:53:17 2007|192.168.40.44|debug [3826]: registred child process: 20714 Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: New HTTP connection open Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: testing denied_hosts Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Client 192.168.40.44 passed access control rules Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Processing a new request line Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: got: GET /ftp.us.debian.org/debian/dists/lenny/Release HTTP/1.1 Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Processing a new request line Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: got: Host: debian.betterworld.us Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Processing a new request line Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: got: User-Agent: Wget Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Processing a new request line Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: got: Connection: close Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Processing a new request line Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: got: Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Resolved request is /ftp.us.debian.org/debian/dists/lenny/Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: new index file: ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: looking for /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: known as index file: Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: download agent: getting http://ftp.us.debian.org/debian/dists/lenny/Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: unlinking ftp.us.debian.org_debian_dists_lenny_Release because it differs from server's version Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: EXPIRED Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: Entering critical section : file download decision Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: file does not exist or so, creating it Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: registered child process: 20715 Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20714]: checks done, can return now Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20715]: Exiting critical section Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20715]: fetcher: try to fetch http://ftp.us.debian.org/debian/dists/lenny/Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20715]: download agent: getting http://ftp.us.debian.org/debian/dists/lenny/Release Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20715]: Entering critical section : Callback, storing the header Fri Nov 23 12:53:17 2007|192.168.40.44|debug [20715]: Exiting critical section Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: Entering critical section : reading the header file Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: Exiting critical section Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: Header sent: HTTP/1.1 200 OK Connection: Close Accept-Ranges: bytes Content-Length: 68547 Content-Type: text/plain Last-Modified: Fri, 23 Nov 2007 08:10:18 GMT Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: ready to send contents of /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: opening file first: /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: read 16384 bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: wrote 16384 (sum: 16384) bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: read 0 bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: read 36864 bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: wrote 36864 (sum: 53248) bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20714]: read 0 bytes Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20715]: Get is back Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20715]: stored http://ftp.us.debian.org/debian/dists/lenny/Release as /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20715]: setting complete flag for ftp.us.debian.org_debian_dists_lenny_Release Fri Nov 23 12:53:18 2007|192.168.40.44|debug [20715]: fetcher exiting Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: read 15299 bytes Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: wrote 15299 (sum: 68547) bytes Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: read 0 bytes Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: complete file found Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: read 0 bytes Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20714]: Package sent Fri Nov 23 12:53:19 2007|192.168.40.44|debug [3826]: Connection from 192.168.40.44 Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: New HTTP connection open Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: testing denied_hosts Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Client 192.168.40.44 passed access control rules Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Processing a new request line Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: got: GET /ftp.us.debian.org/debian/dists/lenny/Release.gpg HTTP/1.1 Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Processing a new request line Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: got: Host: debian.betterworld.us Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Processing a new request line Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: got: User-Agent: Wget Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Processing a new request line Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: got: Connection: close Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Processing a new request line Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: got: Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Resolved request is /ftp.us.debian.org/debian/dists/lenny/Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: new index file: ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: looking for /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: known as index file: Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [3826]: registred child process: 20716 Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: download agent: getting http://ftp.us.debian.org/debian/dists/lenny/Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: unlinking ftp.us.debian.org_debian_dists_lenny_Release.gpg because it differs from server's version Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: EXPIRED Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: Entering critical section : file download decision Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: file does not exist or so, creating it Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20717]: Exiting critical section Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20717]: fetcher: try to fetch http://ftp.us.debian.org/debian/dists/lenny/Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20717]: download agent: getting http://ftp.us.debian.org/debian/dists/lenny/Release.gpg Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: registered child process: 20717 Fri Nov 23 12:53:19 2007|192.168.40.44|debug [20716]: checks done, can return now Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: Entering critical section : Callback, storing the header Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: Exiting critical section Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: Get is back Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: stored http://ftp.us.debian.org/debian/dists/lenny/Release.gpg as /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: setting complete flag for ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20717]: fetcher exiting Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: Entering critical section : reading the header file Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: Exiting critical section Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: Header sent: HTTP/1.1 200 OK Connection: Close Accept-Ranges: bytes Content-Length: 189 Content-Type: application/octet-stream Last-Modified: Fri, 23 Nov 2007 20:13:38 GMT Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: ready to send contents of /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: opening file first: /var/cache/apt-cacher/packages/ftp.us.debian.org_debian_dists_lenny_Release.gpg Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: read 189 bytes Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: wrote 189 (sum: 189) bytes Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: read 0 bytes Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: complete file found Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: read 0 bytes Fri Nov 23 12:53:20 2007|192.168.40.44|debug [20716]: Package sent
