Authentication with correct credentials failing - what do these log messages mean?
Keimo
keimo at bluewin.ch
Fri Apr 29 13:25:25 EDT 2005
Hello
While setting up my first IMAP (cyrus, cyrus-sasl, postfix) server I have
come to a stop.
Can someone tell what the following log messages mean and where things go
wrong. To me it looks like the authenticaiton first succeeds
(auth_success), but then subsequently something goes wrong probably with a
null password. Is this a imap or a sasl-authentication problem?
All parts seem to work fine when tested separately. I have tried with
auxprop (/etc/sasldb2) and with saslauthd pam. However when I try to log in
with my web-client (Squirrelmail at the moment) I get "Unknown user or
password incorrect".
"myuser" has been added to /etc/sasldb2 and to /etc/passwd and seems to be
also in /etc/shadow
Any pointers as to where to look would be greatly appreciated. More info
about the setup at the end of the mail.
Thank you
Keimo
imtest -m login -a myuser localhost
(give correct password)
imapd.log:
Apr 29 16:34:08 mysun imap[2068]: [ID 921384 local6.debug] accepted
connection Apr 29 16:34:10 mysun imap[2068]: [ID 277583 local6.notice]
login: localhost [127.0.0.1] myuser plaintext User logged in
auth.log:
mysun# saslauthd[1999] :rel_accept_lock : released accept lock
saslauthd[1999] :cache_get_rlock : attempting a read lock on slot: 532
saslauthd[1999] :cache_lookup : [login=myuser] [service=] [realm=imap]:
found with valid passwd
saslauthd[1999] :cache_un_lock : attempting to release lock on slot: 532
saslauthd[1999] :do_auth : auth success (cached): [user=myuser]
[service=imap] [realm=]
saslauthd[1999] :do_request : response: OK
saslauthd[2003] :get_accept_lock : acquired accept lock
imtest -m login -a myuser localhost
(give wrong password)
imapd.log:
Apr 29 16:35:03 mysun imap[2068]: [ID 921384 local6.debug] accepted
connection Apr 29 16:35:06 mysun imap[2068]: [ID 914338 local6.notice]
badlogin: localhost [127.0.0.1] plaintext myuser SASL(-13): authentication
failure: checkpass failed
auth.log:
mysun# saslauthd[2003] :rel_accept_lock : released accept lock
saslauthd[2003] :cache_get_rlock : attempting a read lock on slot: 532
saslauthd[2003] :cache_lookup : [login=myuser] [service=] [realm=imap]:
found with invalid passwd, update pending
saslauthd[2003] :cache_un_lock : attempting to release lock on slot: 532
saslauthd[2003] :do_auth : auth failure: [user=myuser]
[service=imap] [realm=] [mech=pam] [reason=PAM auth error]
saslauthd[2005] :get_accept_lock : acquired accept lock
>From my web client
(give correct password)
Here I would like to understand these log messages. Why are there 2 sets of
messages on imapd.log both with badlogin?
Also auth.log looks like things go right first but then the program probably
makes a second pwd check which goes wrong?
imapd.log:
Apr 29 16:36:34 mysun imap[2068]: [ID 921384 local6.debug] accepted
connection Apr 29 16:36:34 mysun imap[2068]: [ID 914338 local6.notice]
badlogin: localhost [127.0.0.1] plaintext myuser SASL(-13): authentication
failure: checkpass failed Apr 29 16:36:37 mysun imap[2068]: [ID 921384
local6.debug] accepted connection Apr 29 16:36:37 mysun imap[2068]: [ID
914338 local6.notice] badlogin: localhost [127.0.0.1] plaintext myuser
SASL(-13): authentication failure: checkpass failed
auth.log:
mysun# saslauthd[2005] :rel_accept_lock : released accept lock
saslauthd[2005] :cache_get_rlock : attempting a read lock on slot: 532
saslauthd[2005] :cache_lookup : [login=myuser] [service=] [realm=imap]:
found with valid passwd
saslauthd[2005] :cache_un_lock : attempting to release lock on slot: 532
saslauthd[2005] :do_auth : auth success (cached): [user=myuser]
[service=imap] [realm=]
saslauthd[2005] :do_request : response: OK
saslauthd[1995] :get_accept_lock : acquired accept lock saslauthd[1995]
:rel_accept_lock : released accept lock
saslauthd[1995] :do_request : NULL password received
saslauthd[1997] :get_accept_lock : acquired accept lock saslauthd[1997]
:rel_accept_lock : released accept lock
saslauthd[1997] :do_request : NULL password received
saslauthd[1999] :get_accept_lock : acquired accept lock
>From my web client
(give wrong password)
imapd.log:
Apr 29 16:37:24 mysun imap[2068]: [ID 921384 local6.debug] accepted
connection Apr 29 16:37:24 mysun imap[2068]: [ID 914338 local6.notice]
badlogin: localhost [127.0.0.1] plaintext myuser SASL(-13): authentication
failure: checkpass failed
auth.log:
mysun# saslauthd[1999] :rel_accept_lock : released accept lock
saslauthd[1999] :cache_get_rlock : attempting a read lock on slot: 532
saslauthd[1999] :cache_lookup : [login=myuser] [service=] [realm=imap]:
found with invalid passwd, update pending
saslauthd[1999] :cache_un_lock : attempting to release lock on slot: 532
saslauthd[1999] :do_auth : auth failure: [user=myuser]
[service=imap] [realm=] [mech=pam] [reason=PAM auth error]
saslauthd[2003] :get_accept_lock : acquired accept lock
/etc/imapd.conf:
configdirectory: /var/imap
partition-default: /var/spool/imap
admins: cyrus
sasl_pwcheck_method: saslauthd
#sasl_pwcheck_method: auxprop
sasl_mech_list: PLAIN LOGIN
My setup
cyrus-sasl-2.1.20
cyrus-imapd-2.2.12
Solaris 8
Configure Cyrus imapd
./configure \
--disable-krb4 \
--with-db-dir=/usr/local/BerkeleyDB.4.3
--with-bdb-libdir=/usr/local/BerkeleyDB.4.3/lib \
--with-bdb-incdir=/usr/local/BerkeleyDB.4.3/include \
--with-openssl=/usr/local/ssl \ --with-perl=/usr/local/bin/perl \
--with-ucdsnmp=/usr/local \ --with-sasl=/usr/local --with-auth=unix
Configure SASL:
./configure \
--with-bdb-libdir=/usr/local/BerkeleyDB.4.3/lib \
--with-bdb-incdir=/usr/local/BerkeleyDB.4.3/include \
--with-openssl=/usr/local/ssl \ --enable-login \
--with-saslauthd=/var/run/saslauthd
Start the programs
/usr/local/sbin/saslauthd -d -c -a pam
postfix start
/usr/cyrus/bin/master &
---
Cyrus Home Page: http://asg.web.cmu.edu/cyrus
Cyrus Wiki/FAQ: http://cyruswiki.andrew.cmu.edu
List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
More information about the Info-cyrus
mailing list