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@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@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@domain.com,208.54.4.133): hit: <hidden> user=gary@domain.com Oct 02 08:21:03 auth: Debug: client out: OK 1 user=gary@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@domain.com,208.54.4.133): hit: gary@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@domain.com uid=89 gid=89 home=/home/vpopmail/domains/domain.com/gary Oct 02 08:21:03 imap-login: Info: Login: user=gary@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@domain2.com,174.17.50.127): miss Oct 02 08:21:06 auth: Debug: vpopmail(teacher@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@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@domain2.com,174.17.50.127): miss Oct 02 08:21:06 auth: Debug: vpopmail(teacher@domain2.com,174.17.50.127): lookup user=teacher domain=domain2.com Oct 02 08:21:06 auth: Debug: master out: USER 3916169217 teacher@domain2.com uid=89 gid=89 home=/home/vpopmail/domains/domain2.com/teacher Oct 02 08:21:06 imap-login: Info: Login: user=teacher@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@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@domain.com,192.168.252.8): hit: <hidden> user=gary@domain.com
Oct 02 08:21:40 auth: Info: password(gary@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@domain.com Oct 02 08:21:42 imap-login: Info: Aborted login (auth failed, 1 attempts): user=gary@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@domain.com,192.168.5.196): hit: <hidden> user=gary@domain.com Oct 02 08:21:55 auth: Debug: client out: OK 1 user=gary@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@domain.com,192.168.5.196): hit: gary@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@domain.com uid=89 gid=89 home=/home/vpopmail/domains/domain.com/gary Oct 02 08:21:55 imap-login: Info: Login: user=gary@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'