[Date Prev][Date Next] [Chronological] [Thread] [Top]

SASL error messages - still don't get it



Hello openldap-software,

  I have managed openldap 2.1.23 and cyrus-sasl 2.1.15 to work
  together with ldapdb auxprop plugin. When client authenticating to
  imap/pop using APOP the authentication and logs are ok, and when
  client authenticating using PLAIN the authentication itself is ok,
  but there are two error messages "pop3d[60154]: no user in db" in
  logs, though slapd.log entries on PLAIN and APOP authentication
  process are pretty the same. Where are those error messages come from?

  And there is "SASL [conn=2957] Failure: Could not open db" error
  message in slapd.log (see below), but it seems that it's not affect
  anything to fail - what is that message about?

  And in imapd.conf there is "sasl_auto_transition: yes" - may it be
  the source of "no user in db" error message?

  Software:
  FreeBSD-4.8R-p13
  openldap-2.1.23
  cyrus-sasl-2.1.15
  cyrus-imapd-2.1.15

  Configs:
  
/usr/local/lib/sasl2/Cyrus.conf:
========================================
pwcheck_method: auxprop
ldapdb_uri: ldap:///
ldapdb_id: cyradm
ldapdb_pw: password
ldapdb_mech: DIGEST-MD5
mech_list: plain login digest-md5 cram-md5
========================================

/usr/local/lib/sasl2/slapd.conf:
========================================
pwcheck_method: auxprop
ldapdb_uri: ldap:///
ldapdb_id: cyradm
ldapdb_pw: password
ldapdb_mech: DIGEST-MD5
========================================

/usr/local/local/etc/openldap/slapd.conf (not full):
========================================
sasl-regexp uid=(.*),cn=.*,cn=auth
    ldap:///ou=users,dc=domain,dc=ru??sub?(uid=$1)
sasl-authz-policy to
========================================

Logs while auth using APOP:

auth.log:
========================================
Dec 17 08:19:54 helios pop3d[66718]: DIGEST-MD5 client step 2
Dec 17 08:19:54 helios pop3d[66718]: DIGEST-MD5 client step 2
Dec 17 08:19:54 helios pop3d[66718]: DIGEST-MD5 client step 3
========================================

slapd.log:
========================================
Dec 17 08:19:54 helios slapd[285]: conn=2957 fd=9 ACCEPT from IP=127.0.0.1:1853 (IP=0.0.0.0:389)
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=0 BIND dn="" method=163
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=1 BIND dn="" method=163
Dec 17 08:19:54 helios slapd[285]: conn=2958 fd=16 ACCEPT from IP=127.0.0.1:1854 (IP=0.0.0.0:389)
Dec 17 08:19:54 helios slapd[285]: conn=2958 op=0 SRCH base="" scope=0 filter="(objectClass=*)"
Dec 17 08:19:54 helios slapd[285]: conn=2958 op=0 SRCH attr=supportedSASLMechanisms
Dec 17 08:19:54 helios slapd[285]: conn=2958 op=0 RESULT tag=101 err=0 text=
Dec 17 08:19:54 helios slapd[285]: SASL [conn=2957] Failure: Could not open db
Dec 17 08:19:54 helios last message repeated 2 times
Dec 17 08:19:54 helios slapd[285]: conn=2958 op=1 UNBIND
Dec 17 08:19:54 helios slapd[285]: conn=2958 fd=16 closed
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=1 BIND authcid="cyradm"
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=1 BIND dn="uid=system,node=33(10),ou=users,dc=startatom,dc=ru" mech=DIGEST-MD5 ssf=128
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=3 SRCH base="uid=system,node=33(10),ou=users,dc=startatom,dc=ru" scope=0 filter="(objectClass=*)"
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=3 SRCH attr=userPassword
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text=
Dec 17 08:19:54 helios slapd[285]: conn=2957 op=4 UNBIND
Dec 17 08:19:54 helios slapd[285]: conn=2957 fd=9 closed
========================================


Logs while auth using PLAIN:

auth.log
========================================
Dec 17 08:22:12 helios pop3d[66717]: DIGEST-MD5 client step 1
Dec 17 08:22:12 helios pop3d[66717]: DIGEST-MD5 client step 1
Dec 17 08:22:12 helios pop3d[66717]: DIGEST-MD5 client step 2
Dec 17 08:22:12 helios pop3d[66717]: DIGEST-MD5 client step 3
Dec 17 08:22:12 helios pop3d[66717]: no user in db
Dec 17 08:22:12 helios pop3d[66717]: no user in db
========================================

slapd.log
========================================
Dec 17 08:22:48 helios slapd[285]: conn=2977 fd=9 ACCEPT from IP=127.0.0.1:1873 (IP=0.0.0.0:389)
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=0 BIND dn="" method=163
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=1 BIND dn="" method=163
Dec 17 08:22:48 helios slapd[285]: conn=2978 fd=16 ACCEPT from IP=127.0.0.1:1874 (IP=0.0.0.0:389)
Dec 17 08:22:48 helios slapd[285]: conn=2978 op=0 SRCH base="" scope=0 filter="(objectClass=*)"
Dec 17 08:22:48 helios slapd[285]: conn=2978 op=0 SRCH attr=supportedSASLMechanisms
Dec 17 08:22:48 helios slapd[285]: conn=2978 op=0 RESULT tag=101 err=0 text=
Dec 17 08:22:48 helios slapd[285]: SASL [conn=2977] Failure: Could not open db
Dec 17 08:22:48 helios last message repeated 2 times
Dec 17 08:22:48 helios slapd[285]: conn=2978 op=1 UNBIND
Dec 17 08:22:48 helios slapd[285]: conn=2978 fd=16 closed
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=1 BIND authcid="cyradm"
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=1 BIND dn="uid=system,node=33(10),ou=users,dc=startatom,dc=ru" mech=DIGEST-MD5 ssf=128
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=3 SRCH base="uid=system,node=33(10),ou=users,dc=startatom,dc=ru" scope=0 filter="(objectClass=*)"
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=3 SRCH attr=userPassword cmusaslsecretPLAIN
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text=
Dec 17 08:22:48 helios slapd[285]: conn=2977 op=4 UNBIND
Dec 17 08:22:48 helios slapd[285]: conn=2977 fd=9 closed
========================================

-- 
Best regards,
 Alexander                          mailto:lan_mailing@startatom.ru