[Dovecot] Intermittent authentication failures
I'm running dovecot with vpopmail. Here's the configuration: [root@wong log]# dovecot -n # 2.0.11: /etc/dovecot/dovecot.conf # OS: Linux 2.6.18-238.9.1.el5 i686 CentOS release 5.6 (Final) auth_cache_size = 32 M auth_mechanisms = plain login digest-md5 cram-md5 auth_username_format = %Lu first_valid_uid = 89 log_path = /var/log/dovecot.log login_greeting = Dovecot toaster ready. mail_fsync = always mail_nfs_index = yes mail_nfs_storage = yes mmap_disable = yes namespace { inbox = yes location = prefix = separator = . type = private } passdb { args = cache_key=%u webmail=127.0.0.1 driver = vpopmail } plugin/quota = maildir protocols = imap ssl_cert =
Most clients use TLS and PLAIN login for verification, which works flawlessly.
I also run SquirrelMail that is slightly dated and has no TLS capability, so it is using CRAM-MD5.
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
I restarted dovecot, and that apparently cleared the problem for one user, but not others.
Is this perhaps a bug in dovecot, or would the problem lie with vpopmail?
TIA for any pointers.
-- -Eric 'shubes'
On 09/30/2011 09:07 AM, 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
I restarted dovecot, and that apparently cleared the problem for one user, but not others.
Is this perhaps a bug in dovecot, or would the problem lie with vpopmail?
TIA for any pointers.
FWIW, I tried digest-md5, and experience the same problem.
Is it possible that passwords are being cached in such a way that different login mechanisms cannot be used by different client programs with the same user account?
-- -Eric 'shubes'
On 09/30/2011 12:59 PM, Eric Shubert wrote:
On 09/30/2011 09:07 AM, 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
I restarted dovecot, and that apparently cleared the problem for one user, but not others.
Is this perhaps a bug in dovecot, or would the problem lie with vpopmail?
TIA for any pointers.
FWIW, I tried digest-md5, and experience the same problem.
Is it possible that passwords are being cached in such a way that different login mechanisms cannot be used by different client programs with the same user account?
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.
I didn't anticipate this behavior, but can live with it. A note about this in the documentation would be nice. I tried to create an account on the wiki for myself to update it, but that doesn't seem to be working presently.
-- -Eric 'shubes'
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.
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'
On Sun, 2011-10-02 at 08:53 -0700, Eric Shubert wrote:
Oct 02 08:21:40 auth: Info: password(gary@domain.com,192.168.252.8): Requested DIGEST-MD5 scheme, but we have only SHA1
Oh. This was vpopmail specific problem. See if this fixes: http://hg.dovecot.org/dovecot-2.0/rev/dbd5f9ec38af
On 10/02/2011 10:28 AM, Timo Sirainen wrote:
On Sun, 2011-10-02 at 08:53 -0700, Eric Shubert wrote:
Oct 02 08:21:40 auth: Info: password(gary@domain.com,192.168.252.8): Requested DIGEST-MD5 scheme, but we have only SHA1
Oh. This was vpopmail specific problem. See if this fixes: http://hg.dovecot.org/dovecot-2.0/rev/dbd5f9ec38af
Thanks Timo. Two things.
First, I don't think this is a comprehensive fix covering all situations, though I could be wrong. One problem with it is that if the password is changed and the plaintext client isn't active, one would need to wait for the cached plaintext record to expire before being able to log in with an encoded password. Another problem might be if there are two separate clients, one using digest-md5 and another using cram-md5, I think the second one used would still fail. No? I'm not sure how best to handle any combination of clients and authentication mechanisms, so I'll leave the solution to your design.
Second and perhaps more importantly, it occurred to me that simply using %u as the cache key might be a significant security hole. If passwords are cached using only the user account, what's to prevent someone else, using another client with the same authentication mechanism at a different IP address, from gaining access to an account that's cached? Perhaps I'm not understanding this right, but I think that using %u%r as the cache key closes this hole, and should probably be recommended in the documentation.
I could (as always) be totally off base on this, so please explain if I'm misunderstanding something.
Thanks again, Timo. Great work on dovecot.
-- -Eric 'shubes'
participants (2)
-
Eric Shubert
-
Timo Sirainen