[GLLUG] Squid thinks time is an hour in the past

[Tim Woodall]

Hi,

Got a bizarre problem with a squid cache. It's as though it thinks the
machine is on BST.

einstein:/var/log/squid# ls -l access.log
-rw-r----- 1 proxy proxy 184889 Dec 15 19:04 access.log
einstein:/var/log/squid# tail -1 access.log
1576436641.982  62463 2001:8b0:fb02:8007::128 TCP_TUNNEL/200 3806
CONNECT shavar.services.mozilla.com:443 - HIER_DIRECT/52.25.50.137 -
einstein:/var/log/squid# date -d '1/1/70+1576436641.982secs'
Sun Dec 15 18:04:01 GMT 2019
einstein:/var/log/squid# date
Sun Dec 15 19:06:11 GMT 2019
einstein:/var/log/squid# cat /etc/timezone 
Europe/London

einstein:/var/log/squid# ls -l /mnt/mirror/ftp/mirror/local/pool/main/d/default-resolv-conf-1.0.deb 
-rw-r--r-- 1 root root 822 Dec 15 18:38 /mnt/mirror/ftp/mirror/local/pool/main/d/default-resolv-conf-1.0.deb

einstein:/var/log/squid# grep default-resolv- access.log
1576401874.161      8 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576406622.851      0 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576429866.730      0 2001:8b0:bfcd:100:216:3eff:fee1:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576431078.518      0 2001:8b0:bfcd:100:216:3eff:fee1:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576435503.627      8 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576435505.662      0 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576436448.060      0 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package
1576436450.111      0 2001:8b0:bfcd:100:216:3eff:fee0:7253 TCP_MEM_HIT/200 1339 GET http://aptmirror17.home.woodall.me.uk/local/pool/main/d/default-resolv-conf-1.0.deb - HIER_NONE/- application/x-debian-package

As you can see, the access log was last written at 19:04 but the
timestamp squid has written into the file is 18:04. The time on the
machine is correct.

This has been bugging me for a while. I have a local repo for packages
and when I update one, and bump the version number, I have to restart
squid in order to flush the old package.

I've taken the time to investigate what could be wrong today. Hopefully,
at 19:38 the new package will start working (instead of getting a "File
has unexpected size" error.) proving my time issue. I can see that I'm
getting a TCP_MEM_HIT/200 from the cache - and so the new file is not
(yet) being served to the client.

Has anyone seen anything like this before? Have I missed a config
setting somewhere? I've scanned though all 8000 lines of
/etc/squid/squid.conf but I didn't see anything that appeared relevant
but I could easily have missed something.

Squid was restarted on 13th December (in fact the entire machine was
rebooted then) so it's not a very long lived process getting confused
about timezone changes.

Tim.