Re: [squid-users] authenticate_ttl not working for digest authentication scheme (v3.1.14)

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_at_zedat.fu-berlin.de
Zentraleinrichtung für Datenverarbeitung | http://www.zedat.fu-berlin.de