[squid-users] Squid exiting all on its own

[Amos Jeffries]

On 10/02/2016 6:48 a.m., Nick Walke wrote:
> We're running Squid 3.5.  We noticed today that Squid "exited normally" at
> 11:10:55 our time.  Here's a log sample:
> 
> 2016/02/09 11:09:10 kid1| hold write on SSL connection on FD 13
> 2016/02/09 11:09:14 kid1| hold write on SSL connection on FD 16
> 2016/02/09 11:09:23 kid1| hold write on SSL connection on FD 18
> 2016/02/09 11:09:36 kid1| hold write on SSL connection on FD 18
> 2016/02/09 11:10:11 kid1| hold write on SSL connection on FD 13
> 2016/02/09 11:10:15 kid1| hold write on SSL connection on FD 16
> 2016/02/09 11:10:23 kid1| hold write on SSL connection on FD 18
> 2016/02/09 11:10:24| Current Directory is /run

First oddity. A master-level Squid process suddenly initializing (no
'kidN' ID).

> 2016/02/09 11:10:24 kid1| Preparing for shutdown after 312 requests
> 2016/02/09 11:10:24 kid1| Waiting 30 seconds for active connections to
> finish

This means an explicit shutdown command has been delivered to the
running Squid service, 'kid1' is obeying.

That could be done via a cachemgr request [not in your case, your
squid.conf does not unlock that action], a system 'kill' signal, or a
'squid -k shutdown' (or -k restart) signal.

Possibly by that other Squid that said "Current Directory is /run".

OR, possibly by something else and the other one talking in the log is a
new squid process trying to startup (but failing below)


> 2016/02/09 11:10:24 kid1| Closing HTTP port [::]:3129
> 2016/02/09 11:10:24 kid1| Closing HTTPS port [::]:3130
> 2016/02/09 11:10:26| Squid is already running!  Process ID 30116

Another squid process is being attempted to be started before the
existing 'kid1' is finished shutting down.

Are you using systemd or upstart? I have seen this type of overlap when
there is a daemon manager watching the "squid -k shutdown" process to
guess when Squid was shutdown. But that process just emits a SIGHUP and
exits ... way, way, way, way faster than the real Squid shutdown time.
 (a whole 29+ seconds faster in this log).


> 2016/02/09 11:10:55 kid1| Shutdown: NTLM authentication.
> 2016/02/09 11:10:55 kid1| Shutdown: Negotiate authentication.
> 2016/02/09 11:10:55 kid1| Shutdown: Digest authentication.
> 2016/02/09 11:10:55 kid1| Shutdown: Basic authentication.
> 2016/02/09 11:10:55 kid1| Shutting down...
> 2016/02/09 11:10:55 kid1| storeDirWriteCleanLogs: Starting...
> 2016/02/09 11:10:55 kid1|   Finished.  Wrote 0 entries.
> 2016/02/09 11:10:55 kid1|   Took 0.00 seconds (  0.00 entries/sec).
> CPU Usage: 0.992 seconds = 0.901 user + 0.091 sys
> Maximum Resident Size: 59104 KB
> Page faults with physical i/o: 0
> 2016/02/09 11:10:55 kid1| Logfile: closing log syslog:local4.info
> 2016/02/09 11:10:55 kid1| Open FD UNSTARTED     6 DNS Socket IPv6
> 2016/02/09 11:10:55 kid1| Open FD READ/WRITE    7 DNS Socket IPv4
> 2016/02/09 11:10:55 kid1| Squid Cache (Version 3.5.13): Exiting normally.
> 
> Here's my squid config: https://gist.github.com/nwalke/55fea584352016149180
> 
> Here's my squid configure:
> https://gist.github.com/nwalke/a9fea476cf7b3326ef14
> 
> We get these "kid1| hold write on SSL connection on FD" messages a lot, is
> this something to be concerned about?

Squid has some data queued up to be sent on the server connection but
its being held back due to peek or stare action currently taking place.

I suspect its not a major issue, but I'm not sure why its at such a high
debug level. Christos may be able to answer better.


> 
> Does anything in this jump out to anyone as a problem?  I can't figure out
> what's causing it to stop.
> 

It being told to. See above.

Amos