Timo Sirainen wrote:
On Mon, 2009-01-05 at 14:33 +0100, Tom Sommer wrote:
Sorry to bump this, but I can still reproduce it - I have enabled
auth_debug now to attempt to provide some more details.
Actually enable auth_debug_passwords=yes. It then also logs what's seen
in the cache entries.
dovecot: Jan 20 09:01:18 Info: auth(default):
cache(u...@example.com,127.0.0.1): miss
dovecot: Jan 20 09:01:18 Info: auth-worker(default):
sql(u...@example.com,127.0.0.1): query: SELECT username as user,
plainpassword as password, nopassword FROM cyrususers WHERE username =
'u...@example.com' AND password = PASSWORD('SECRET') AND active = 1
dovecot: Jan 20 09:01:18 Info: auth-worker(default):
sql(u...@example.com,127.0.0.1): unknown user
dovecot: Jan 20 09:01:20 Info: auth(default): client out: FAIL 1
user=u...@example.com
dovecot: Jan 20 09:01:20 Info: imap-login: Disconnected (auth failed, 1
attempts): user=<u...@example.com>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.2
dovecot: Jan 20 09:01:32 Info: auth(default):
cache(u...@example.com,127.0.0.1): hit:
dovecot: Jan 20 09:01:32 Info: auth(default):
cache(u...@example.com,127.0.0.1): User unknown
dovecot: Jan 20 09:01:34 Info: auth(default): client out: FAIL 1
user=u...@example.com
It appears the user missed the cache, a SQL lookup is performed (which
returns 1 record, I tested the query directly) - however for some reason
the lookup is set as Unknown User, a state which it then keeps.
Obviously I can adjust this with auth_cache_negative_ttl, but I presumed
the default value was always 0
Setting auth_cache_negative_ttl = 0 now and awaiting results
--
Tom Sommer
