[squid-users] Squid + kerberos, all childrens are busy

[Amos Jeffries]

On 9/07/2015 10:32 p.m., Дмитрий Рукавцов wrote:
> 
> 
> 
>>> Четверг,  9 июля 2015, 22:06 +12:00 от Amos Jeffries <squid3 at treenet.co.nz>:
>>>
>>> On 9/07/2015 9:54 p.m., Дмитрий Рукавцов wrote:
>>>>  Hello, i have a problem here :) System - freebsd 10.1, squid 3.5.5 + kerberos (MIT), 50 users total.
>>>>
>>>> Without any auth my squid works fine, system is not loaded. When i enable Kerberos auth internet slowly goes down and crushing after a while, at logs i see:
>>>>
>>>> 2015/07/09 11:47:14 kid1| WARNING: All 60/60 negotiateauthenticator processes are busy. 
>>>> 2015/07/09 11:47:14 kid1| WARNING: 72 pending requests queued
>>>>
>>>
>>> So 50 users / 60 helpers ... how many requests per second? and how
>>> fast/slow is the helper responding?
> Could you clarify how I can get value of requests per second and respond?

The cachemgr "info" report. From the cachemgr.cgi tool, or "squidclient
mgr:info" command line, or
http://$visible_hostname:3128/squid-internal-mgr/info

 Or calculated from a quick count of the access.log lines over a few mins.



>>
>>>> If i put 100 childrens at config it won't help too.
>>>>
>>>
>>> Please define "wont help".
> It will take more time, but all 100 will be busy too.
>>
>>>>
>>>> Server shutting down in like 7 mins, i can't even restart squid(system endless trying to kill squid PID), can't even make kill -9, not working (but system load is very low)
>>>>
>>>> Can you please help me to find out what is wrong? Is there any way to monitor what happens with negotiate_kerberos_auth  processes ?
>>>
>>> -d helper parameter should log to cache.log what its doing.
>>
> Debugs show like 3-4 message per second like:
> 
> negotiate_kerberos_pac.cc(376): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Got PAC data of lengh 624
> negotiate_kerberos_pac.cc(180): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Found 5 rids
> negotiate_kerberos_pac.cc(188): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: Info: Got rid: 513
> negotiate_kerberos_pac.cc(188): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: Info: Got rid: 3692
> negotiate_kerberos_pac.cc(188): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: Info: Got rid: 4268
> negotiate_kerberos_pac.cc(188): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: Info: Got rid: 4622
> negotiate_kerberos_pac.cc(188): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: Info: Got rid: 4623
> negotiate_kerberos_pac.cc(256): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Got DomainLogonId S-1-5-21-1708537768-1580818891-2146958067
> negotiate_kerberos_pac.cc(278): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Found 1 ExtraSIDs
> negotiate_kerberos_pac.cc(327): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Got ExtraSid S-1-5-21-1708537768-1580818891-2146958067-4107
> negotiate_kerberos_pac.cc(456): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: INFO: Read 620 of 624 bytes
> negotiate_kerberos_auth.cc(778): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: DEBUG: Groups group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/AQIAAA== group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/bA4AAA== group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/rBAAAA== group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/DhIAAA== group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/DxIAAA== group=AQUAAAAAAAUVAAAAqDfWZcthOV7z+vd/CxAAAA==
> negotiate_kerberos_auth.cc(783): pid=1456 :2015/07/09 13:26:48| negotiate_kerberos_auth: DEBUG: AF oYGyMIGvoAMKAQChCwYJKoZIgvcSAQICooGaBIGXYIGUBgkqhkiG9xIBAgICAG+BhDCBgaADAgEFoQMCAQ+idTBzoAMCAReibARqY4fSYtg+X4HhiH8dFmWxdn3wxtoKKZzEfUjLYibMoy0XAAWgkSYVXgC7gxO7cgCkOofEqZQhi/GKa4NZqn2dQqOJU/3y4zkPqBP9Ialh//BL5ov03L5BqjgthrbYbrcxJTo57EJIdO8O1g== avialex
> 
> And errors like:
> 2015/07/09 13:28:03 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
> All my friends get the same error, but their squid is working fine.
> 
> Don't see anything else
> 

Aha. So your users browsers are sending NTLM auth instead of Kerberos.
That is at least one part of the problem. NTLM handshake can take whole
seconds and places a lot of extra load on the helpers. To resolve these
the users software needs fixing to use Kerberos properly when Negotiate
is offered.

The other part is figuring out what amount of helpers is needed to meet
the load requirements. With NTLM it is usually several hundred.

Amos