[Dovecot] SOLVED Intermittent authentication failures

[Eric Shubert]

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'