RE: [squid-users] Squid/NTLM and site timeouts

>> All,
>>
>> I have a Squid and NTLM implementation. I've had one for years, and always have been pretty pleased with it. There has always been one quirk, and I've decided to ask about it in case there is a known solution.
>>
>> Typically, NTLM requires a back and forth of authentication. Whenever a site is very slow to respond, or down and times out, my browsers display an authentication prompt to the end user. I noticed this happens sometimes, even, after the full page is loaded, and an advertisement or some other element takes a long time to load.
>> This behaviour sounds more like the slowness is being caused by NTLM itself being slow or failing. The domain lookups and connections do not even start to happen until NTLM>login to the proxy is already successfully completed.
>> The prompt is a browser feature. Squid has nothing to do with it besides the coincidence that the browser may choose to do it whenever Squid asks for credentials. The modern>ones usually only try it after automatic logins like NTLM have been tried and failed.
>>
>> You would think that is the case, but it's not. I can demonstrate this. I've created a PHP page that just loads text.
>> http://www.pendulus.org/loaddirect.php
>>
>> Squid logs:
>> 1329009688.461 0 192.168.71.117 TCP_DENIED/407 4051 GET http://www.pendulus.org/loaddirect.php - NONE/- text/html
>> 1329009688.552 1 192.168.71.117 TCP_DENIED/407 4308 GET http://www.pendulus.org/loaddirect.php - NONE/- text/html
>> 1329009688.822 187 192.168.71.117 TCP_MISS/200 330 GET http://www.pendulus.org/loaddirect.php jgauthier DIRECT/69.135.186.43 text/html
>>
>> This worked exactly as expected.
>>
>> I created one with a 30 second delay:
>> http://www.pendulus.org/loadshortpause.php
>>
>> Squid logs:
>> 1329010018.324 1 192.168.71.117 TCP_DENIED/407 4067 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html
>> 1329010018.473 0 192.168.71.117 TCP_DENIED/407 4332 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html
>> 1329010048.720 30194 192.168.71.117 TCP_MISS/200 330 GET
>> http://www.pendulus.org/loadshortpause.php jgauthier
>> DIRECT/69.135.186.43 text/html
>>
>> Notice my username does not appear until *after* the 30 second pause that's inside the web page.

>Yes. Note how the requests which have incomplete NTLM have "NONE/-"
>logged for the server details.

>What that log shows is that successful NTLM credentials were recieved by Squid (jgauthier), then DNS was performed (DIRECT) , then the server
>(69.135.186.43) was contacted. The entire process took 30.194 seconds.

>>
>> Lastly, I created one with a 300 second delay in it.
>> http://www.pendulus.org/loadpause.php
>>
>> Squid logs:
>> 1329009789.283 0 192.168.71.117 TCP_DENIED/407 4047 GET http://www.pendulus.org/loadpause.php - NONE/- text/html
>> 1329009789.372 0 192.168.71.117 TCP_DENIED/407 4312 GET http://www.pendulus.org/loadpause.php - NONE/- text/html
>> 1329009909.439 120024 192.168.71.117 TCP_MISS/000 0 GET http://www.pendulus.org/loadpause.php jgauthier DIRECT/69.135.186.43 -
>> 1329009909.534 0 192.168.71.117 TCP_DENIED/407 4331 GET http://www.pendulus.org/loadpause.php - NONE/- text/html
>>
>> At the point the second two log entries are created, the browser also prompted me for credentials again.
>> The gap in time is two minutes.
>> After two minutes, I am re-prompted from the browser, this is what I am describing. The situation I want to stop from occurring.
>
>>This one shows is that successful NTLM credentials were recieved by
>>Squid (jgauthier), then DNS was performed (DIRECT) , then the server
>>(69.135.186.43) was contacted. Then after 120.024 seconds the connection
>>between Squid and client got closed ("/000" in column 4) before anything
>>was received by the server for delivery (0 bytes in column 5).
>
>>The browser decides to do the popup based on what it is aware of: An
>>NTLM login which never got a successful response to the final stage when
>>full credentials were sent. Try again (with different credentials).
>
>>You can try increasing
>>http://www.squid-cache.org/Doc/config/persistent_request_timeout/ if it
>>was Squid. But be aware of simialr limits in TCP firewall state tracking
>>and NAT systems, and timeouts in browser as well which all result in the
>>same connection closure.

I understand what you're saying, but I don't think the process you've described works the way you've described it.
For instance, you've said:

"What that log shows is that successful NTLM credentials were recieved by Squid (jgauthier), then DNS was performed (DIRECT) , then the server
(69.135.186.43) was contacted. The entire process took 30.194 seconds."

In regards to this log entry:

1329010018.324 1 192.168.71.117 TCP_DENIED/407 4067 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html
1329010018.473 0 192.168.71.117 TCP_DENIED/407 4332 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html
1329010048.720 30194 192.168.71.117 TCP_MISS/200 330 GET http://www.pendulus.org/loadshortpause.php jgauthier DIRECT/69.135.186.43 text/html

Except the server is contacted at 1329010018, not 1329010048.

Using the logs on a new connection:

1329053373.745 0 192.168.71.117 TCP_DENIED/407 4103 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html
1329053373.832 2 192.168.71.117 TCP_DENIED/407 4375 GET http://www.pendulus.org/loadshortpause.php - NONE/- text/html

date && netstat -an|grep 69.135
Sun Feb 12 08:29:46 EST 2012
tcp6 0 0 192.168.74.119:44708 69.135.186.43:80 ESTABLISHED

1329053404.104 30196 192.168.71.117 TCP_MISS/200 330 GET http://www.pendulus.org/loadshortpause.php jgauthier DIRECT/69.135.186.43 text/html

As you can see, when I look at the netstat output the connection to 65.135.184.43 is established long before the last log file entry, where you are indicating it was established according to squid.

Squid is logging the contact after the page is fully loaded. Apache agrees that the contact time starts before squid logs it.
64.129.117.119 - - [12/Feb/2012:08:29:34 -0500] "GET /loadshortpause.php HTTP/1.1" 200 19

It does seem you are correct in this regard:
 "Then after 120.024 seconds the connection between Squid and client got closed ("/000" in column 4) before anything was received by the server for delivery (0 bytes in column 5)."

And maybe the option you mentioned will help correct that.

As far as NTLM goes, I've done monitoring on the server to determine that NTLM itself is not the bottleneck.
I will look into your option, to see if it helps with the two minute time out. Otherwise, I wish the browser would just "start over" :P

Jason
Received on Sun Feb 12 2012 - 14:07:39 MST