Bug 388088

This can cause significant confusion and problems since though squid still ends up running it is not listening on all the required ports. 

So it's up, but not quite up.

I also notice that:
/etc/logrotate.d/squid 
does not have the sharedscripts directive for all three logs.

By the way, won't doing "/etc/init.d/squid reload" for a log rotate break existing downloads?

Seems a really bad idea to restart services for log rotation, rather than just doing log rotation. 

Doing a reload during rotation also means that if someone messed up the squid.conf file by mistake, you end up having the users noticing during log rotation time, which is usually when you don't want to be called.

If there is no reload signal, then squid continues writing into rotate logfiles, as the file handle is not changed.

Will have a look...

Please attache (via attachement mechanism - and do NOT paste)
 /etc/squid/squid.conf
 /var/log/squid/cache.log

Your provided information and assumptions aren't enough for me for debugging.

We have changed /etc/logrotate.d/squid
To:
/var/log/squid/cache.log {
    compress
    dateext
    maxage 365
    rotate 99
    size=+1024k
    notifempty
    missingok
    create 640 squid root
    sharedscripts
    postrotate
     /usr/sbin/squid -k rotate
    endscript
}

/var/log/squid/access.log {
    compress
    dateext
    maxage 365
    rotate 99
    size=+4096k
    notifempty
    missingok
    create 640 squid root
    sharedscripts
    postrotate
     /usr/sbin/squid -k rotate
    endscript
}

/var/log/squid/store.log {
    compress
    dateext
    maxage 365
    rotate 99
    size=+4096k
    notifempty
    missingok
    create 640 squid root
    sharedscripts
    postrotate
     /usr/sbin/squid -k rotate
    endscript
}
--
This appears to rotate logs successfully for us while avoiding the squid rebind, and thus hopefully the problem. 

Not sure if this problem will occur for a /etc/init.d/squid restart 

Created attachment 214198 [details]
squid.conf

Created attachment 214199 [details]
cache.log when stuff went wrong

2008/05/04 03:50:19| commBind: Cannot Bind socket FD 72 to 202.75.242.254:3128: (98) Address already in use
2008/05/04 03:50:19| commBind: Cannot bind socket FD 72 to 202.75.242.254:8080: (98) Address already in use

Created attachment 214200 [details]
cache.log when stuff started ok

this is when stuff was ok.

Not sure if it's relevant but for some reason the Pinger socket was closed in both OK logs and not closed in the bad log.

Created attachment 214201 [details]
much earlier cache.log when the rotate, reconfigure went ok

I now think the Pinger bit is not relevant. This is because when squid didn't rebind properly, it stopped receiving user requests, and so that's why the pinger never got around to closing.

Sorry, but at the moment I'm unable to reproduce it.

Currently I've got the feeling that the old squid isn't dying fast enough and therefore hanging a bit to long in the system, locking the port.

So, you've to do some more debugging for me.

Next time when this happens do (as root) in a command line terminal the following command. This might be time critical, so please don't wait.

- Identify the processes which are listening on the 3128 port:
  lsof -i | egrep '(ndl-aas|3128).*LISTEN'

==> This will report you the process name (1st column) and the process id (2nd column).

==> If there is only one process reported, you're too late. Try again.

- Check whether both processes have the same process ids (pid) or at least parent pids. ==> read the output.

- If not, identify the process ids and check when both processes were
started:
  ps  -Flp <<pid1>> <<pid2>>

Tell me the result.

==> still NEEDINFO

It's probably as what you say, perhaps it is a race condition and only happens under load and is related to the size of the logs being rotated (since suse 10.2 runs /etc/init.d/squid reload for each log file - 3 times).

As far as I know it doesn't happen that often on our live sites but it definitely has happened on more than two sites on different occasions- and given that squid does continue running (albeit only on 127.0.0.1), I do not think that somebody did something strange directly to the site.

The other explanation would be the 202.75.242.254 interface going down around the time of log rotation _and_ somehow coming back up again (since it was obviously not down). I think this is very unlikely to be the cause.

For what it's worth, I have also noticed that at some sites squid is restarting the redirectors as root instead of squid!

Anyway, as per comment #6, we are taking measures to avoid requiring squid to attempt to release and rebind to ports in the first place (which appears to occur with suse's /etc/init.d/squid reload ). So instead of doing suse 10.2 style of squid -k rotate; sleep 2; squid -k reconfigure potentially for _each_ squid log to be rotated, we will now just do squid -k rotate once for all 3 squid logs. 

This should hopefully avoid the following undesirables (estimate in brackets):
1) squid not rebinding on all required ports (very likely to work)
2) squid reloading its config every day when admins might not be around (100%)
3) squid restarting redirector processes as root (might help, but not a big issue)

However this is also likely to reduce the odds of us reproducing the problem and doing your suggested debugging.

Ok, I've added "sharedscripts" to the logrotate configuration.

Please note, that we don't fix this for older SUSE Linux version as it is no security issue (policy). Please note either, that the logrotate config file is a config file and therefore not replaced on next security update at your site.

fixed versions submitted.

Just like to point out that as per #6 we didn't just add the sharedscripts directive we also changed:

/etc/init.d/squid reload 

to:

/usr/sbin/squid -k rotate

Thanks. We'll be using our version of the config file anyway.

Sorry, but a long time ago there was an issue, because we didn't do that.
The bad news is, that I cannot find the reference anymore.