[squid-users] leaking memory in squid 3.4.8 and 3.4.7.

Fri Oct 3 09:00:24 UTC 2014

Amos Jeffries wrote:

[dd]

> > Bingo! After setting "ident_access deny all" squid does not grow 
> > infinitely any more. However, it remains a major CPU hog.
> > 
> 
> Yay. Any news on the bug patch?

Will try during the weekend. I can live without IDENT lookups for a
while, they are not very important, just convenient.

> 
> Note that from the same "CPU hog" cycles you are now getting around 2x
> the HTTP traffic throughput.

I have found out that the major CPU hog is the NTLM authenticator.
After I disabled the NTLM helper, there is no high CPU utilization.
Which brings the next question, please see below :)

> 
> You have the delay pools feature configured. It is a wasteful consumer
> of CPU cycles. 
>  2) moving the delay pools limitation into kernel QoS systems.

1. I am planning to use the delay pool to restrict bandwidth differently
to different users. The kernerl QoS system (ipfw pipes in my case)
cannot do that for non-local users.

2. Delay pools worked fine in squid27, never a problem. I don't see a
reason why they should become a problem in squid3.

> Also NTLM authentication is used, that doubles the HTTP
> request overheads on each new TCP connection.
>  1) converting from NTLM to Kerberos authentication.

I have tried to setup Kerberos (negotiate) authentication, but all I
see is Internet Explorer asking users for their login/password.

I am pretty sure that I have setup the server part correctly. At least
when I do the following:

kinit -t /usr/local/etc/squid/squid.keytab HTTP/proxy.sibptus.transneft.ru

I obtain the TGT issued to HTTP/proxy.sibptus.transneft.ru at SIBPTUS.TRANSNEFT.RU

My squid.keytab contains:

Vno  Type              Principal
  0  arcfour-hmac-md5 HTTP/proxy.sibptus.transneft.ru at SIBPTUS.TRANSNEFT.RU

To me, this means the Kerberos server part is correct. I don't know for
the present how to debug it further. Any Kerberos gurus?

Below is a bit of debug from negotiate_kerberos_auth

negotiate_kerberos_auth.cc(212): pid=96295 :2014/10/03 15:45:53 kid1|   Took 0.41 seconds (80933.38 objects/sec).
2014/10/03 15:45:53| negotiate_kerberos_auth: INFO: Starting version 3.0.4sq
2014/10/03 15:45:53 kid1| Beginning Validation Procedure
2014/10/03 15:45:53 kid1|   Completed Validation Procedure
2014/10/03 15:45:53 kid1|   Validated 33380 Entries
2014/10/03 15:45:53 kid1|   store_swap_size = 878994.00 KB
negotiate_kerberos_auth.cc(258): pid=96289 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96289 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96289 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96290 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96290 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96290 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96292 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96292 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96292 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96293 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96293 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96293 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96294 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96294 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96294 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96295 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96295 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96295 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
negotiate_kerberos_auth.cc(258): pid=96291 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96291 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96291 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).
negotiate_kerberos_auth.cc(311): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Decode 'TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' (decoded length: 40).
negotiate_kerberos_auth.cc(321): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: WARNING: received type 1 NTLM token
2014/10/03 15:45:53 kid1| ERROR: Negotiate Authentication validating user. Result: {result=BH, notes={message: received type 1 NTLM token; }}
negotiate_kerberos_auth.cc(258): pid=96287 :2014/10/03 15:45:53| negotiate_kerberos_auth: DEBUG: Got 'YR TlRMTVNTUAABAAAAl4II4gAAAAAAAAAAAAAAAAAAAAAGAbEdAAAADw==' from squid (length: 59).

-- 
Victor Sudakov,  VAS4-RIPE, VAS47-RIPN
sip:sudakov at sibptus.tomsk.ru