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.ca
