Hi, can anybody confirm the problem I have? And do you need more information? Thanks, Jan On 07/21/11 18:39, Jan Sievers wrote: > Hi everybody, > > maybe somebody can enlighten me how re-validation of the HA1 digest > works. I am struggling to get it the way I want. > > To fight abuse, here we have to ensure, that blocked or deleted users, > cannot log in to squid anymore after some not so long time. > > Unfortunately, with squid 3.1.14 and digest authentication it seems, > that logging in is possible endlessly until the squid daemon is restarted. > > For testing I set > > > authenticate_ttl 1 minute > > > and expected, that after 1 minute, my digest helper script gets asked > again for the HA1 hash of the user in question. But it does not happen. > > After doing some tests I found out, that when I set > > > authenticate_cache_garbage_interval 1 minute > > > the digest backend is actually asked after 1 minute of *browsing > inactivity* (That is understandable, since it's just a garbage collection). > > This could be a workaround, but even for production I would have to set > this value relatively low, since the backend gets only asked, if no > browsing activity was recognized and browsers do a lot on there own > these days. And for a strict abuse countermeasure it is not sufficient. > > Maybe you can help me on that. > > Here comes a commented debug log file with "debug_options 29,6": > > [I removed some nonce related things, like > authenticateDigestNonceCacheCleanup] > > == First request without user in auth cache == > > 2011/07/21 15:58:48.109| authenticateValidateUser: Auth_user_request was > NULL! > 2011/07/21 15:58:48.109| authenticateAuthenticate: broken auth or no > proxy_auth header. Requesting auth header. > 2011/07/21 15:58:48.110| authenticateDigestNonceNew: created nonce > 0x90700d0 at 1311256728 > > == User enters credentials == > > 2011/07/21 15:58:56.175| authenticateAuthenticate: no connection > authentication type > 2011/07/21 15:58:56.175| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.175| authenticateDigestAuthenticateuser: user > 'testuser' validated OK > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.175| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:58:56.176| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > > == Auth cache cleanup: AuthUser still fresh - does not get deleted == > > 2011/07/21 15:59:02.136| AuthUser::cacheCleanup: Cleaning the user cache now > 2011/07/21 15:59:02.136| AuthUser::cacheCleanup: Current time: 1311256742 > 2011/07/21 15:59:02.136| AuthUser::cacheCleanup: Cache entry: > Type: 3 > Username: testuser > expires: 1311256796 > references: 1 > 2011/07/21 15:59:02.136| AuthUser::cacheCleanup: Finished cleaning the > user cache. > > == Second request shortly after - the digest backend should not get asked == > > 2011/07/21 15:59:11.926| authenticateAuthenticate: no connection > authentication type > 2011/07/21 15:59:11.927| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 15:59:11.927| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:59:11.927| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:59:11.927| authenticateDigestAuthenticateuser: user > 'testuser' validated OK > 2011/07/21 15:59:11.927| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:59:11.927| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:59:11.927| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 15:59:11.930| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > > == Auth cache cleanup: AuthUser still fresh - does not get deleted == > > 2011/07/21 16:00:02.136| AuthUser::cacheCleanup: Cleaning the user cache now > 2011/07/21 16:00:02.136| AuthUser::cacheCleanup: Current time: 1311256802 > 2011/07/21 16:00:02.136| AuthUser::cacheCleanup: Cache entry: > Type: 3 > Username: testuser > expires: 1311256811 > references: 1 > 2011/07/21 16:00:02.136| AuthUser::cacheCleanup: Finished cleaning the > user cache. > > == Another request more than 60 seconds after asking the backend, it > should ask again, but does not == > > 2011/07/21 16:00:05.726| authenticateAuthenticate: no connection > authentication type > 2011/07/21 16:00:05.727| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 16:00:05.727| authenticateDigestDecode: Unexpected or invalid > nonce received > 2011/07/21 16:00:05.727| AuthUser::AuthUser: Initialised auth_user > '0x8d94238' with refcount '0'. > 2011/07/21 16:00:05.727| authenticateValidateUser: Auth_user '0x8d94238' > is broken for it's scheme. > 2011/07/21 16:00:05.727| authenticateValidateUser: Auth_user '0x8d94238' > is broken for it's scheme. > 2011/07/21 16:00:05.727| authenticateDigestNonceNew: created nonce > 0x90700d0 at 1311256805 > 2011/07/21 16:00:05.727| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > 2011/07/21 16:00:05.727| AuthUser::~AuthUser: Freeing auth_user > '0x8d94238' with refcount '0'. > 2011/07/21 16:00:05.732| authenticateAuthenticate: no connection > authentication type > 2011/07/21 16:00:05.733| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.733| authenticateDigestAuthenticateuser: user > 'testuser' validated OK > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.733| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:00:05.735| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > > == Cache cleanup: AuthUser is still fresh - does not get deleted == > > 2011/07/21 16:01:02.136| AuthUser::cacheCleanup: Cleaning the user cache now > 2011/07/21 16:01:02.136| AuthUser::cacheCleanup: Current time: 1311256862 > 2011/07/21 16:01:02.136| AuthUser::cacheCleanup: Cache entry: > Type: 3 > Username: testuser > expires: 1311256865 > references: 1 > 2011/07/21 16:01:02.136| AuthUser::cacheCleanup: Finished cleaning the > user cache. > > == Cache cleanup: AuthUser is not fresh - does get deleted == > > 2011/07/21 16:02:02.136| AuthUser::cacheCleanup: Cleaning the user cache now > 2011/07/21 16:02:02.136| AuthUser::cacheCleanup: Current time: 1311256922 > 2011/07/21 16:02:02.136| AuthUser::cacheCleanup: Cache entry: > Type: 3 > Username: testuser > expires: 1311256865 > references: 1 > 2011/07/21 16:02:02.136| AuthUser::cacheCleanup: Removing user testuser > from cache due to timeout. > 2011/07/21 16:02:02.136| AuthUser::~AuthUser: Freeing auth_user > '0x9028ea8' with refcount '0'. > 2011/07/21 16:02:02.137| AuthUser::~AuthUser: removing usernamehash > entry '0x9032308' > 2011/07/21 16:02:02.137| AuthUser::cacheCleanup: Finished cleaning the > user cache. > > == Another request: Digest backend gets asked again. == > > 2011/07/21 16:02:10.196| authenticateAuthenticate: no connection > authentication type > 2011/07/21 16:02:10.196| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 16:02:10.196| authenticateDigestDecode: Unexpected or invalid > nonce received > 2011/07/21 16:02:10.196| AuthUser::AuthUser: Initialised auth_user > '0x9028ea8' with refcount '0'. > 2011/07/21 16:02:10.196| authenticateValidateUser: Auth_user '0x9028ea8' > is broken for it's scheme. > 2011/07/21 16:02:10.196| authenticateValidateUser: Auth_user '0x9028ea8' > is broken for it's scheme. > 2011/07/21 16:02:10.196| authenticateDigestNonceNew: created nonce > 0x90700d0 at 1311256930 > 2011/07/21 16:02:10.197| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > 2011/07/21 16:02:10.197| AuthUser::~AuthUser: Freeing auth_user > '0x9028ea8' with refcount '0'. > 2011/07/21 16:02:10.200| authenticateAuthenticate: no connection > authentication type > 2011/07/21 16:02:10.201| AuthUserRequest::AuthUserRequest: initialised > request 0x9075fc0 > 2011/07/21 16:02:10.201| AuthUser::AuthUser: Initialised auth_user > '0x9028ea8' with refcount '0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateDigestAuthenticateuser: user > 'testuser' validated OK > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.201| authenticateAuthUserAddIp: user 'testuser' has > been seen at a new IP address (192.0.2.1:50911) > 2011/07/21 16:02:10.201| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.202| authenticateValidateUser: Validated Auth_user > request '0x9075fc0'. > 2011/07/21 16:02:10.205| AuthUserRequest::~AuthUserRequest: freeing > request 0x9075fc0 > > > Thanks in advance for any help, > Jan > -- Jan Sievers | Freie Universität Berlin | sievers@xxxxxxxxxxxxxxxxxx Zentraleinrichtung für Datenverarbeitung | http://www.zedat.fu-berlin.de
