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