[Dovecot] SOLVED Intermittent authentication failures
Eric Shubert
ejs at shubes.net
Sun Oct 2 18:53:19 EEST 2011
On 10/01/2011 08:16 AM, Timo Sirainen wrote:
> On Fri, 2011-09-30 at 16:24 -0700, Eric Shubert wrote:
>>>> CRAM-MD5 works sometimes:
>>>> Sep 30 08:15:43 imap-login: Info: Login: user=<userA at domain.com>,
>>>> method=CRAM-MD5, rip=192.168.252.8, lip=192.168.252.14, mpid=20301
>>>>
>>>> but (seemingly more frequently) the authentication fails:
>>>> Sep 30 08:16:41 imap-login: Info: Aborted login (auth failed, 1
>>>> attempts): user=<userA at domain.com>, method=CRAM-MD5, rip=192.168.252.8,
>>>> lip=192.168.252.14
>>>>
>> My problem was indeed with the password caching. I changed
>> cache_key=%u
>> to
>> cache_key=%u%r
>> and that cleared things up.
>>
>> I expect that this is only a problem when different client programs use
>> different login mechanisms, which was the case with this particular
>> group of users.
>
> Auth mechanism shouldn't affect caching or vice versa. Maybe the %r just
> happens to work around the real problem, which might still be there but
> just less frequent.. Logs with auth_debug=yes could have been helpful in
> figuring this out.
Ask and ye shall receive:
Oct 02 08:21:03 auth: Debug: client in: AUTH 1 PLAIN
service=imap secured lip=192.168.6.14 rip=208.54.4.133
lport=143 rport=43401 resp=<hidden>
Oct 02 08:21:03 auth: Debug: cache(gary at domain.com,208.54.4.133): hit:
<hidden> user=gary at domain.com
Oct 02 08:21:03 auth: Debug: client out: OK 1 user=gary at domain.com
Oct 02 08:21:03 auth: Debug: master in: REQUEST 546963457 11596
1 9d5ae9a5778c4e1da32bfe9de1027163
Oct 02 08:21:03 auth: Debug: userdb-cache(gary at domain.com,208.54.4.133):
hit: gary at domain.com uid=89 gid=89
home=/home/vpopmail/domains/domain.com/gary
Oct 02 08:21:03 auth: Debug: master out: USER 546963457
gary at domain.com uid=89 gid=89
home=/home/vpopmail/domains/domain.com/gary
Oct 02 08:21:03 imap-login: Info: Login: user=<gary at domain.com>,
method=PLAIN, rip=208.54.4.133, lip=192.168.6.14, mpid=11607, TLS
Oct 02 08:21:05 auth: Debug: auth client connected (pid=11609)
Oct 02 08:21:05 auth: Debug: client in: AUTH 1 CRAM-MD5
service=imap secured lip=192.168.6.14 rip=174.17.50.127
lport=993 rport=50696
Oct 02 08:21:05 auth: Debug: client out: CONT 1
PDU5NjE3NTM4NTk4OTA0MTIuMTMxNzU2ODg2NUB3b25nLnIzaW52ZXN0aWdhdGlvbnMuY29tPg==
Oct 02 08:21:06 auth: Debug: client in: CONT<hidden>
Oct 02 08:21:06 auth: Debug: cache(teacher at domain2.com,174.17.50.127): miss
Oct 02 08:21:06 auth: Debug:
vpopmail(teacher at domain2.com,174.17.50.127): lookup user=teacher
domain=domain2.com
Oct 02 08:21:06 auth: Debug: client out: OK 1
user=teacher at domain2.com
Oct 02 08:21:06 auth: Debug: master in: REQUEST 3916169217 11609
1 42c98a70d61d08e4b1440028faf5324a
Oct 02 08:21:06 auth: Debug:
userdb-cache(teacher at domain2.com,174.17.50.127): miss
Oct 02 08:21:06 auth: Debug:
vpopmail(teacher at domain2.com,174.17.50.127): lookup user=teacher
domain=domain2.com
Oct 02 08:21:06 auth: Debug: master out: USER 3916169217
teacher at domain2.com uid=89 gid=89
home=/home/vpopmail/domains/domain2.com/teacher
Oct 02 08:21:06 imap-login: Info: Login: user=<teacher at domain2.com>,
method=CRAM-MD5, rip=174.17.50.127, lip=192.168.6.14, mpid=11612, TLS
Oct 02 08:21:35 imap(gary at domain.com): Info: Disconnected: Logged out
bytes=361/1161
Oct 02 08:21:40 auth: Debug: auth client connected (pid=11627)
Oct 02 08:21:40 auth: Debug: client in: AUTH 1 DIGEST-MD5
service=imap lip=192.168.252.14 rip=192.168.252.8
lport=143 rport=41155
Oct 02 08:21:40 auth: Debug: client out: CONT 1
cmVhbG09IiIsbm9uY2U9InpkR3VZcFd0T25iUWpQM3hHOVloemc9PSIscW9wPSJhdXRoIixjaGFyc2V0PSJ1dGYtOCIsYWxnb3JpdGhtPSJtZDUtc2VzcyI=
Oct 02 08:21:40 auth: Debug: client in: CONT<hidden>
Oct 02 08:21:40 auth: Debug: cache(gary at domain.com,192.168.252.8): hit:
<hidden> user=gary at domain.com
Oct 02 08:21:40 auth: Info: password(gary at domain.com,192.168.252.8):
Requested DIGEST-MD5 scheme, but we have only SHA1
Oct 02 08:21:42 auth: Debug: client out: FAIL 1 user=gary at domain.com
Oct 02 08:21:42 imap-login: Info: Aborted login (auth failed, 1
attempts): user=<gary at domain.com>, method=DIGEST-MD5, rip=192.168.252.8,
lip=192.168.252.14
Oct 02 08:21:55 auth: Debug: auth client connected (pid=11629)
Oct 02 08:21:55 auth: Debug: client in: AUTH 1 PLAIN
service=imap secured lip=192.168.6.14 rip=192.168.5.196
lport=993 rport=4605 resp=<hidden>
Oct 02 08:21:55 auth: Debug: cache(gary at domain.com,192.168.5.196): hit:
<hidden> user=gary at domain.com
Oct 02 08:21:55 auth: Debug: client out: OK 1 user=gary at domain.com
Oct 02 08:21:55 auth: Debug: master in: REQUEST 875167745 11629
1 126eea78f45a1270bea10f8f939545fa
Oct 02 08:21:55 auth: Debug:
userdb-cache(gary at domain.com,192.168.5.196): hit: gary at domain.com
uid=89 gid=89 home=/home/vpopmail/domains/domain.com/gary
Oct 02 08:21:55 auth: Debug: master out: USER 875167745
gary at domain.com uid=89 gid=89
home=/home/vpopmail/domains/domain.com/gary
Oct 02 08:21:55 imap-login: Info: Login: user=<gary at domain.com>,
method=PLAIN, rip=192.168.5.196, lip=192.168.6.14, mpid=11630, TLS
The user gary first connects using TMobile phone (208.54.4.133), then a
subsequent attempt via Squirrelmail/webmail (192.168.252.8) fails.
Outlook (192.168.5.196) is also in there. Outlook and TMobile both use
PLAIN with TLS, and they get along fine. Squirrelmail doesn't presently
support TLS, so needs to use cram-md5 or digest-md5, which fails with
the cached entry from one of the other clients.
Thank you so much for your terrific work with Dovecot, Timo. It is truly
a premier piece of work.
--
-Eric 'shubes'
More information about the dovecot
mailing list