RE: [squid-users] Interminted TCP_DENIED

Thanks Amos.
I ran the debug mode and took some output from cache.log. Can you take a peek at the end of this log file? I see a "Nonce count doesn't match" around the time it starts to fail authentication again. The logs below were generated by:
1) open browser, navigate to google.com
2) authenticate with user test/test (successful)
3) open latimes.com
4) get authentication challenge in browser unexpectedly after some resources load successfully
5) enter credentials once more
6) another authentication challenges come up immediately - stop test.

Do you think this could be the problem you mentioned? Unless my system just tends to exacerbate this bug for some reason I can't imagine this wouldn't be identified before (totally unusable w/ digest authentication). I'm using fedora 12, compiled myself on the system.

I'd be happy to try 3.2 and do some heavy testing, but when I looked at 3.0 and 3.1 a while back a lot of features weren't ported over still, which is why I went with 2.7. The logdaemon is one obvious feature. I don't remember if there were others. Do you know if logdaemon will be in 3.2, or are already there? I should review the list of unported features again.

2010/09/20 17:22:48| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:22:48| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:22:48| authenticateDigestNonceNew: created nonce 0x856b588 at 1285017768
2010/09/20 17:22:50| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateAuthUserRequestFree: freeing request 0x8558b50
2010/09/20 17:22:50| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.
2010/09/20 17:22:50| authenticateValidateUser: Validated Auth_user request '0x8558b50'.

   <<< 90 lines of similar/repeated log statements removed >>>

2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authDigestNonceIsValid: Nonce count doesn't match
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestNonceNew: created nonce 0x83d23d8 at 1285017776
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authDigestNonceIsValid: Nonce already invalidated
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestNonceNew: created nonce 0x856b9c0 at 1285017776
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authDigestNonceIsValid: Nonce already invalidated
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestNonceNew: created nonce 0x856b6e0 at 1285017776
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authDigestNonceIsValid: Nonce already invalidated
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestNonceNew: created nonce 0x83d23b0 at 1285017776
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authDigestNonceIsValid: Nonce already invalidated
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestNonceNew: created nonce 0x856bb48 at 1285017776
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:22:56| authenticateAuthenticate: no connection authentication type
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:22:56| authenticateAuthUserRequestFree: freeing request 0x858b940

  <<< 371 lines of similar/repeating log statements removed >>>

2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ee538'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ee538'.
2010/09/20 17:23:02| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ee538'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ee538'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ee538'.
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85ec4c0
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85b8df8
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85eb780
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:23:02| authenticateAuthenticate: no connection authentication type
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:23:02| authenticateDigestAuthenticateuser: user 'test' validated OK
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x858b940'.
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85bcba0
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x8564e50
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85ee538
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85ea0a8
2010/09/20 17:23:02| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:02| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:02| authenticateDigestNonceNew: created nonce 0x85ea3a8 at 1285017782
2010/09/20 17:23:02| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:02| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:02| authenticateDigestNonceNew: created nonce 0x85f2f10 at 1285017782
2010/09/20 17:23:02| authenticateAuthenticate: no connection authentication type
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ea0a8'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ea0a8'.
2010/09/20 17:23:02| authDigestNonceIsValid: Nonce count doesn't match
2010/09/20 17:23:02| authenticateDigestAuthenticateuser: user 'test' validated OK but nonce stale
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ea0a8'.
2010/09/20 17:23:02| authenticateValidateUser: Validated Auth_user request '0x85ea0a8'.
2010/09/20 17:23:02| authenticateDigestNonceNew: created nonce 0x85ec798 at 1285017782
2010/09/20 17:23:02| authenticateAuthUserRequestFree: freeing request 0x85ea0a8
2010/09/20 17:23:03| authenticateAuthUserRequestFree: freeing request 0x858a958
2010/09/20 17:23:03| authenticateAuthUserRequestFree: freeing request 0x857ffd0
2010/09/20 17:23:03| authenticateAuthUserRequestFree: freeing request 0x857fda0
2010/09/20 17:23:03| authenticateAuthUserRequestFree: freeing request 0x8585ae8
2010/09/20 17:23:03| authenticateAuthUserRequestFree: freeing request 0x858b940
2010/09/20 17:23:03| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:03| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:03| authenticateDigestNonceNew: created nonce 0x856b938 at 1285017783
2010/09/20 17:23:03| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:03| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:03| authenticateDigestNonceNew: created nonce 0x8585da8 at 1285017783
2010/09/20 17:23:05| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:05| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:05| authenticateDigestNonceNew: created nonce 0x8581090 at 1285017785
2010/09/20 17:23:05| authenticateValidateUser: Auth_user_request was NULL!
2010/09/20 17:23:05| authenticateAuthenticate: broken auth or no proxy_auth header. Requesting auth header.
2010/09/20 17:23:05| authenticateDigestNonceNew: created nonce 0x857fe58 at 1285017785

-----Original Message-----
From: Amos Jeffries [mailto:squid3_at_treenet.co.nz]
Sent: Sunday, September 19, 2010 4:33 PM
To: squid-users_at_squid-cache.org
Subject: Re: [squid-users] Interminted TCP_DENIED

On Sun, 19 Sep 2010 12:37:38 -0700, "David Parks" <davidparks21_at_yahoo.com>
wrote:
> I've simplified things as far as I can think to and still get what
appear
> to
> be random TCP_DENIED/407 errors after I've been authenticated.
>
> Using Squid 2.7 STABLE 9, I'm now just using the digest_pw_auth
> authenticator with a single user pw file of test:test.
>
> If I turn off authentication there's no problem. But with
> authentication
on
> I can't get much further than a page or two of sites like Yahoo.com or
> LATimes.com (sites with many resources) before I get a 407.
>
> I've run some wireshark captures and could post the http header
> request/responses if that helps any. I don't know the digest
authentication
> protocol well enough to follow all the nonce transitions and all of
> that
to
> see if it's a problem.
>
> Here is my squid.conf in hopes that someone might have some ideas on
> direction I could take in debugging this.
>
> Is there any way to get more info from Squid about why it's throwing
407's?

debug_options 29,6

Squid has a few strange things going on with ref-counting of the credentials. Particularly relevant would be race conditions erasing the past credentials if a new validation re-check fails.

NP: 3.2 has had an overhaul in the credentials management to remove such bugs. But the digest side has not yet had strong testing. If you are able to help out with the testing and fixing any found issues there it may prove more reliable.

Amos
Received on Mon Sep 20 2010 - 21:39:51 MDT