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@xxxxxxxxxxxxx] Sent: Sunday, September 19, 2010 4:33 PM To: squid-users@xxxxxxxxxxxxxxx Subject: Re: Interminted TCP_DENIED On Sun, 19 Sep 2010 12:37:38 -0700, "David Parks" <davidparks21@xxxxxxxxx> 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
