On Monday, our usually very stable Squid 2.6stable20 server acted up, due to what appears to be a problem with the ntlm_auth helpers. No changes have been made to the system recently, with the exception of recompiling to allow for logs >2Gb last month. Prior to that, the system had been stable since Mar 2008. The logs below show a FATAL stop after too many queued auths, which could be due to slow AD DCs combined with spyware on clients hammering the proxy. But the odd thing is after the restart at 19:36 on Feb 1, our MRTG snmp stats showed a gradual decline in active clients from a normal 650 down to 0, over a period of 24 hours. All other snmp stats appear normal.
These two events appear to be related, but I'm not sure how or where to look next.
cache.log showing the abend:
===========
2010/02/01 19:36:12| WARNING: All basicauthenticator processes are busy.
2010/02/01 19:36:12| WARNING: up to 16 pending requests queued
2010/02/01 19:36:12| storeDirWriteCleanLogs: Starting...
2010/02/01 19:36:12| WARNING: Closing open FD 17
2010/02/01 19:36:12| commSetEvents: epoll_ctl(EPOLL_CTL_DEL): failed on fd=17: (1) Operation not permitted
2010/02/01 19:36:12| 65536 entries written so far.
2010/02/01 19:36:12| 131072 entries written so far.
<snip
2010/02/01 19:36:17| Finished. Wrote 2393562 entries.
2010/02/01 19:36:17| Took 5.0 seconds (477102.8 entries/sec).
FATAL: Too many queued basicauthenticator requests (16 on 5)
Squid Cache (Version 2.6.STABLE20): Terminated abnormally.
CPU Usage: 51624.410 seconds = 30518.320 user + 21106.090 sys
Maximum Resident Size: 0 KB
Page faults with physical i/o: 2
Memory usage for squid via mallinfo():
total space in arena: 1727844 KB
Ordinary blocks: 1658823 KB 788411 blks
Small blocks: 0 KB 0 blks
Holding blocks: 25956 KB 13 blks
Free Small blocks: 0 KB
Free Ordinary blocks: 69020 KB
Total in use: 1684779 KB 96%
Total free: 69020 KB 4%
[2010/02/01 19:36:18, 1] utils/ntlm_auth.c:manage_squid_request(1594)
fgets() failed! dying..... errno=1 (Operation not permitted)
[2010/02/01 19:36:18, 1] utils/ntlm_auth.c:manage_squid_request(1594)
fgets() failed! dying..... errno=1 (Operation not permitted)
[2010/02/01 19:36:18, 1] utils/ntlm_auth.c:manage_squid_request(1594)
fgets() failed! dying..... errno=1 (Operation not permitted)
[2010/02/01 19:36:18, 1] utils/ntlm_auth.c:manage_squid_request(1594)
fgets() failed! dying..... errno=1 (Operation not permitted)
[2010/02/01 19:36:18, 1] utils/ntlm_auth.c:manage_squid_request(1594)
fgets() failed! dying..... errno=1 (Operation not permitted)
2010/02/01 19:36:21| Starting Squid Cache version 2.6.STABLE20 for i686-pc-linux-gnu...
2010/02/01 19:36:21| Process ID 2918
2010/02/01 19:36:21| With 16384 file descriptors available
2010/02/01 19:36:21| Using epoll for the IO loop
2010/02/01 19:36:21| Performing DNS Tests...
2010/02/01 19:36:21| Successful DNS name lookup tests...
2010/02/01 19:36:21| DNS Socket created at 0.0.0.0, port 43908, FD 6
2010/02/01 19:36:21| Adding nameserver 208.67.222.222 from squid.conf
2010/02/01 19:36:21| Adding nameserver 208.67.220.220 from squid.conf
2010/02/01 19:36:21| helperOpenServers: Starting 5 'ntlm_auth' processes
2010/02/01 19:36:21| Unlinkd pipe opened on FD 16
2010/02/01 19:36:21| Swap maxSize 225280000 KB, estimated 17329230 objects
2010/02/01 19:36:21| Target number of buckets: 866461
2010/02/01 19:36:21| Using 1048576 Store buckets
2010/02/01 19:36:21| Max Mem size: 1048576 KB
2010/02/01 19:36:21| Max Swap size: 225280000 KB
2010/02/01 19:36:21| Store logging disabled
2010/02/01 19:36:21| Rebuilding storage in /cache1 (CLEAN)
2010/02/01 19:36:21| Rebuilding storage in /cache2 (CLEAN)
2010/02/01 19:36:21| Rebuilding storage in /cache3 (CLEAN)
2010/02/01 19:36:21| Rebuilding storage in /cache4 (CLEAN)
2010/02/01 19:36:21| Using Least Load store dir selection
2010/02/01 19:36:21| Current Directory is /root/squid-2.6.STABLE20
2010/02/01 19:36:21| Loaded Icons.
2010/02/01 19:36:22| Accepting proxy HTTP connections at 72.2.0.12, port 80, FD 25.
2010/02/01 19:36:22| Accepting SNMP messages on port 3401, FD 26.
2010/02/01 19:36:22| Ready to serve requests.
2010/02/01 19:36:22| Store rebuilding is 0.7% complete
-- Shawn Wright I.T. Manager, Shawnigan Lake School http://www.shawnigan.caReceived on Thu Feb 04 2010 - 04:14:40 MST
This archive was generated by hypermail 2.2.0 : Thu Feb 04 2010 - 12:00:04 MST