https://bugzilla.novell.com/show_bug.cgi?id=388088
Summary: squid sometimes fails to rebind to its ports on log
rotation
Product: openSUSE 10.2
Version: Final
Platform: Other
OS/Version: Other
Status: NEW
Severity: Normal
Priority: P5 - None
Component: Other
AssignedTo: bnc-team-screening@forge.provo.novell.com
ReportedBy: lyeoh@inter-touch.com
QAContact: qa@suse.de
Found By: ---
Squid _sometimes_ fails to rebind to its ports on log rotation.
OS: opensuse 10.2
Squid version: opensuse squid-2.6.STABLE5-7
Note: we have 60 redirectors attached to squid.
/var/log/squid/cache.log
2008/05/06 03:32:48| commBind: Cannot bind socket FD 72 to 202.75.242.254:3128:
(98) Address already in use
2008/05/06 03:32:48| commBind: Cannot bind socket FD 72 to 202.75.242.254:8080:
(98) Address already in use
I suspect this happens when squid is somehow still busy with something
(redirectors or some pending connection?), so the sockets are not unbound by
squid before squid tries to reattach.
This might be because opensuse's /etc/init.d/squid reload does squid -k rotate,
sleep 2, squid -k reconfigure. And /etc/logrotate.d/squid has /etc/init.d/squid
reload as postrotate for the various squid log files.
What possibly happens is 2 seconds after squid -k rotate, the squid is still
busy restarting the 60 redirectors, then squid -k reload is called, and it is
not possible to get rid of the previous squid socket binds in time.
We will be trying a workaround of just doing squid -k rotate for log rotation.
Log follows (note the HB: DEAD: <PID> messages are from the redirector
processes when they die. squid is configured to bind to 127.0.0.1:3128
127.0.0.1:8080 202.75.242.254:3128 202.75.242.254:8080 ).
2008/05/06 03:32:38| storeDirWriteCleanLogs: Starting...
HB: DEAD: 24962
HB: DEAD: 24964
HB: DEAD: 24960
HB: DEAD: 24976
HB: DEAD: 24977
HB: DEAD: 24981
HB: DEAD: 24959
HB: DEAD: 24967
HB: DEAD: 24970
HB: DEAD: 24975
HB: DEAD: 24982
HB: DEAD: 24941
HB: DEAD: 24916
HB: DEAD: 24979
HB: DEAD: 24917
HB: DEAD: 24958
HB: DEAD: 24921
2008/05/06 03:32:38| 65536 entries written so far.
HB: DEAD: 24926
HB: DEAD: 24929
HB: DEAD: 24966
HB: DEAD: 24908
HB: DEAD: 24947
HB: DEAD: 24915
HB: DEAD: 24920
HB: DEAD: 24923
HB: DEAD: 24925
HB: DEAD: 24928
HB: DEAD: 24930
HB: DEAD: 24961
HB: DEAD: 24969
HB: DEAD: 24938
HB: DEAD: 24957
HB: DEAD: 24942
HB: DEAD: 24974
HB: DEAD: 24948
2008/05/06 03:32:38| 131072 entries written so far.
2008/05/06 03:32:38| Finished. Wrote 138190 entries.
2008/05/06 03:32:38| Took 0.2 seconds (599582.6 entries/sec).
2008/05/06 03:32:38| aioSync: flushing pending I/O operations
2008/05/06 03:32:38| aioSync: done
2008/05/06 03:32:38| logfileRotate: /var/log/squid/access.log
2008/05/06 03:32:38| Pinger socket opened on FD 9
2008/05/06 03:32:38| helperOpenServers: Starting 60 'redirector.pl' processes
2008/05/06 03:32:44| Reconfiguring Squid Cache (version 2.6.STABLE5)...
2008/05/06 03:32:44| FD 72 Closing HTTP connection
2008/05/06 03:32:44| FD 73 Closing HTTP connection
2008/05/06 03:32:44| FD 74 Closing HTTP connection
2008/05/06 03:32:44| FD 75 Closing HTTP connection
2008/05/06 03:32:44| Closing Pinger socket on FD 9
2008/05/06 03:32:44| Cache dir '/var/cache/squid' size remains unchanged at
4096000 KB
2008/05/06 03:32:44| Logformat for 'itt' is ' %ts.%03tu %6tr %>a %Ss/%03Hs %