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

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