[squid-users] kid registration timed out

Mon Feb 8 15:08:04 UTC 2016

I'm seeing a couple of intermittent problems (which of course I haven't 
been able to reproduce on a non-production server).  Does anyone have 
any idea what might be the cause?:

When I restart squid, sometimes it fails to restart properly.  In the 
logs, I see something like:

03:43:27 kid1| Starting Squid Cache version 3.5.11 for 
x86_64-redhat-linux-gnu...
03:43:27 kid1| Service Name: squidnocache
03:43:27 kid1| Process ID 8763
03:43:27 kid1| Process Roles: worker
03:43:27 kid1| With 16384 file descriptors available
03:43:27 kid1| Initializing IP Cache...
03:43:27 kid1| DNS Socket created at [::], FD 10
03:43:27 kid1| DNS Socket created at 0.0.0.0, FD 11
03:43:27 kid1| Adding nameserver ::1 from /etc/resolv.conf
03:43:27 kid1| Adding nameserver 127.0.0.1 from /etc/resolv.conf
03:43:27 kid1| Adding domain sexeys.somerset.sch.uk from /etc/resolv.conf
03:43:27 kid1| helperOpenServers: Starting 5/32 'ssl_crtd' processes
03:43:27 kid1| helperOpenServers: Starting 0/50 'negotiate_wrapper_auth' 
processes
03:43:27 kid1| helperStatefulOpenServers: No 'negotiate_wrapper_auth' 
processes needed.
03:43:27 kid1| helperOpenServers: Starting 0/50 'basic_pam_auth' processes
03:43:27 kid1| helperOpenServers: No 'basic_pam_auth' processes needed.
03:43:27 kid1| helperOpenServers: Starting 5/10 'squid-preauth' processes
03:43:27 kid1| helperOpenServers: Starting 5/10 'squid-sslpeek' processes
03:43:27 kid1| Logfile: opening log stdio:/var/log/squid-nocache/access.log
03:43:27 kid1| Local cache digest enabled; rebuild/rewrite every 
3600/3600 sec
03:43:27 kid1| Store logging disabled
03:43:27 kid1| Swap maxSize 0 + 0 KB, estimated 0 objects
03:43:27 kid1| Target number of buckets: 0
03:43:27 kid1| Using 8192 Store buckets
03:43:27 kid1| Max Mem  size: 0 KB
03:43:27 kid1| Max Swap size: 0 KB
03:43:27 kid1| Using Least Load store dir selection
03:43:27 kid1| Set Current Directory to /var/spool/squid-nocache
03:43:27 kid1| Finished loading MIME types and icons.
03:43:27 kid1| HTCP Disabled.
03:43:27 kid1| Configuring Parent [::1]/3129/0
03:43:27 kid1| Squid plugin modules loaded: 0
03:43:27 kid1| Adaptation support is on
03:43:28 kid1| storeLateRelease: released 0 objects
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.182 seconds = 0.125 user + 0.057 sys
Maximum Resident Size: 83088 KB
Page faults with physical i/o: 13
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.189 seconds = 0.130 user + 0.059 sys
Maximum Resident Size: 83104 KB
Page faults with physical i/o: 0
03:43:33 kid1| Closing HTTP port [::]:3128
03:43:33 kid1| Closing HTTP port [::]:8080
03:43:33 kid1| Closing HTTP port [::]:3130
03:43:33 kid1| Closing HTTPS port [::]:3131
03:43:33 kid1| storeDirWriteCleanLogs: Starting...
03:43:33 kid1|   Finished.  Wrote 0 entries.
03:43:33 kid1|   Took 0.00 seconds (  0.00 entries/sec).
FATAL: kid1 registration timed out
Squid Cache (Version 3.5.11): Terminated abnormally.
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.188 seconds = 0.126 user + 0.062 sys
Maximum Resident Size: 83104 KB
Page faults with physical i/o: 0
CPU Usage: 0.184 seconds = 0.116 user + 0.068 sys
Maximum Resident Size: 83088 KB
Page faults with physical i/o: 0
03:43:37 kid1| Set Current Directory to /var/spool/squid-nocache
03:43:37 kid1| Starting Squid Cache version 3.5.11 for 
x86_64-redhat-linux-gnu...
03:43:37 kid1| Service Name: squidnocache
03:43:37 kid1| Process ID 8833
03:43:37 kid1| Process Roles: worker
03:43:37 kid1| With 16384 file descriptors available
03:43:37 kid1| Initializing IP Cache...
03:43:37 kid1| DNS Socket created at [::], FD 10
03:43:37 kid1| DNS Socket created at 0.0.0.0, FD 11
03:43:37 kid1| Adding nameserver ::1 from /etc/resolv.conf
03:43:37 kid1| Adding nameserver 127.0.0.1 from /etc/resolv.conf
03:43:37 kid1| Adding domain sexeys.somerset.sch.uk from /etc/resolv.conf
03:43:37 kid1| helperOpenServers: Starting 5/32 'ssl_crtd' processes
03:43:37 kid1| helperOpenServers: Starting 0/50 'negotiate_wrapper_auth' 
processes
03:43:37 kid1| helperStatefulOpenServers: No 'negotiate_wrapper_auth' 
processes needed.
03:43:37 kid1| helperOpenServers: Starting 0/50 'basic_pam_auth' processes
03:43:37 kid1| helperOpenServers: No 'basic_pam_auth' processes needed.
03:43:37 kid1| helperOpenServers: Starting 5/10 'squid-preauth' processes
03:43:37 kid1| helperOpenServers: Starting 5/10 'squid-sslpeek' processes
03:43:37 kid1| Logfile: opening log stdio:/var/log/squid-nocache/access.log
03:43:37 kid1| Local cache digest enabled; rebuild/rewrite every 
3600/3600 sec
03:43:37 kid1| Store logging disabled
03:43:37 kid1| Swap maxSize 0 + 0 KB, estimated 0 objects
03:43:37 kid1| Target number of buckets: 0
03:43:37 kid1| Using 8192 Store buckets
03:43:37 kid1| Max Mem  size: 0 KB
03:43:37 kid1| Max Swap size: 0 KB
03:43:37 kid1| Using Least Load store dir selection
03:43:37 kid1| Set Current Directory to /var/spool/squid-nocache
03:43:37 kid1| Finished loading MIME types and icons.
03:43:37 kid1| HTCP Disabled.
03:43:37 kid1| Configuring Parent [::1]/3129/0
03:43:37 kid1| Squid plugin modules loaded: 0
03:43:37 kid1| Adaptation support is on
03:43:38 kid1| storeLateRelease: released 0 objects
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.177 seconds = 0.124 user + 0.053 sys
Maximum Resident Size: 83088 KB
Page faults with physical i/o: 0
Squid Cache (Version 3.5.11): Terminated abnormally.
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.189 seconds = 0.127 user + 0.062 sys
Maximum Resident Size: 83072 KB
Page faults with physical i/o: 0
CPU Usage: 0.191 seconds = 0.130 user + 0.061 sys
Maximum Resident Size: 83072 KB
Page faults with physical i/o: 0
03:43:43 kid1| Closing HTTP port [::]:3128
03:43:43 kid1| Closing HTTP port [::]:8080
03:43:43 kid1| Closing HTTP port [::]:3130
03:43:43 kid1| Closing HTTPS port [::]:3131
03:43:43 kid1| storeDirWriteCleanLogs: Starting...
03:43:43 kid1|   Finished.  Wrote 0 entries.
03:43:43 kid1|   Took 0.00 seconds (  0.00 entries/sec).
FATAL: kid1 registration timed out
Squid Cache (Version 3.5.11): Terminated abnormally.
CPU Usage: 0.193 seconds = 0.137 user + 0.056 sys
Maximum Resident Size: 83104 KB
Page faults with physical i/o: 0

There are actually 4 workers, but I have excluded the log lines for 
"kid[2-9]" as they seem to show exactly the same as kid1.  I can't see 
any indication of why it is blowing up, other than "FATAL: kid1 
registration timed out" (and identical time outs for the other workers). 
  I seem to be left with a Squid process still running (so my monitoring 
doesn't alert me that Squid isn't running), but it doesn't service 
requests.  This isn't too bad if I'm manually restarting squid during 
the day, but if squid gets restarted in the night due to a package 
upgrade I can be left with a dead proxy that requires manual intervention.

The second problem, which may or may not be related, is that if Squid 
crashes (e.g. an assert()), it usually automatically restarts, but some 
times it fails and I see this logged:

FATAL: Ipc::Mem::Segment::open failed to 
shm_open(/squidnocache-cf__metadata.shm): (2) No such file or directory

Similar to the first problem, when this happens I'm still left with a 
squid process running, but it isn't servicing any requests.  I realise 
that it is a bug for Squid to crash in the first place, but it's 
compounded by the occasional complete loss of service when it happens.

Any help would be appreciated.  Thanks. :)

-- 
  - Steve Hill
    Technical Director
    Opendium Limited     http://www.opendium.com

Direct contacts:
    Instant messager: xmpp:steve at opendium.com
    Email:            steve at opendium.com
    Phone:            sip:steve at opendium.com

Sales / enquiries contacts:
    Email:            sales at opendium.com
    Phone:            +44-1792-824568 / sip:sales at opendium.com

Support contacts:
    Email:            support at opendium.com
    Phone:            +44-1792-825748 / sip:support at opendium.com