Multiple Passdb's - Order

[Jean-Louis Dupond]

Hi,

Today I upgraded my dovecot to a newer version (2.2.9 debian
wheezy-backports)
At that moment I also reconfigured the whole thing a bit nicer.

Now I stumbled on the following issue.

In my configuration I use 2 backends (LDAP & passwd-file).
passdb {
  args = scheme=CRYPT username_format=%u /etc/dovecot/users
  driver = passwd-file
}
passdb {
  args = /etc/dovecot/dovecot-ldap.conf.ext
  driver = ldap
}
userdb {
  args = uid=vmail gid=vmail home=/var/vmail/%d/%n
  driver = static
}

Now this worked fine before. But if I tested it, LDAP logins worked, and
passwd-file logins failed.

Failed log (user is only in the passwd-file):
Aug 01 21:31:55 auth: Debug: Loading modules from directory:
/usr/lib/dovecot/modules/auth
Aug 01 21:31:55 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 01 21:31:55 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_pgsql.so
Aug 01 21:31:55 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_sqlite.so
Aug 01 21:31:55 auth: Debug: Loading modules from directory:
/usr/lib/dovecot/modules/auth
Aug 01 21:31:55 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libauthdb_ldap.so
Aug 01 21:31:55 auth: Debug: Read auth token secret from
/var/run/dovecot/auth-token-secret.dat
Aug 01 21:31:55 auth: Debug: passwd-file /etc/dovecot/users: Read 10
users in 0 secs
Aug 01 21:31:55 auth: Debug: auth client connected (pid=5516)
Aug 01 21:31:55 auth: Debug: client in: AUTH    1    PLAIN   
service=imap    secured    session=c34kcZb/uwBbtKLu    lip=xxx   
rip=xxxx    lport=993    rport=52411
Aug 01 21:31:55 auth: Debug: client passdb out: CONT    1   
Aug 01 21:31:55 auth: Debug: client in: CONT    1    xxxxx (previous
base64 data may contain sensitive data)
Aug 01 21:31:55 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
miss
Aug 01 21:31:55 auth: Debug: ldap(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
pass search: base=uid=info at xxx.com,ou=mail,dc=dupie,dc=be scope=subtree
filter=(&(objectClass=posixAccount)(uid=info at xxx.com))
fields=uid,userPassword
Aug 01 21:31:55 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
miss
Aug 01 21:31:55 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
miss
Aug 01 21:31:55 auth: Debug:
passwd-file(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>): lookup:
user=info at xxx.com file=/etc/dovecot/users
Aug 01 21:31:57 auth: Debug: client passdb out: FAIL    1   
user=info at xxx.com    temp
Aug 01 21:31:57 auth: Debug: client in: AUTH    2    PLAIN   
service=imap    secured    session=c34kcZb/uwBbtKLu    lip=xxx   
rip=xxx    lport=993    rport=52411    resp=xxx (previous base64 data
may contain sensitive data)
Aug 01 21:32:01 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
miss
Aug 01 21:32:01 auth: Debug: ldap(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
pass search: base=uid=info at xxx.com,ou=mail,dc=dupie,dc=be scope=subtree
filter=(&(objectClass=posixAccount)(uid=info at xxx.com))
fields=uid,userPassword
Aug 01 21:32:01 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
miss
Aug 01 21:32:01 auth: Debug: cache(info at xxx.com,xxx,<c34kcZb/uwBbtKLu>):
hit: {CRAM-MD5}19192922.....
Aug 01 21:32:03 auth: Debug: client passdb out: FAIL    2   
user=info at xxx.com    temp

As you see it returned a FAIL, but the password was retrieved from the
users file (see the cache hit).

Now I changed the order of the passdb's in my config, to make
passwd-file come first, and then LDAP.
And what happend now, it started working ...

Logs:
Aug 01 21:30:23 auth: Debug: Loading modules from directory:
/usr/lib/dovecot/modules/auth
Aug 01 21:30:23 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_mysql.so
Aug 01 21:30:23 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_pgsql.so
Aug 01 21:30:23 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libdriver_sqlite.so
Aug 01 21:30:23 auth: Debug: Loading modules from directory:
/usr/lib/dovecot/modules/auth
Aug 01 21:30:23 auth: Debug: Module loaded:
/usr/lib/dovecot/modules/auth/libauthdb_ldap.so
Aug 01 21:30:23 auth: Debug: Read auth token secret from
/var/run/dovecot/auth-token-secret.dat
Aug 01 21:30:23 auth: Debug: passwd-file /etc/dovecot/users: Read 10
users in 0 secs
Aug 01 21:30:23 auth: Debug: auth client connected (pid=5459)
Aug 01 21:30:24 auth: Debug: client in: AUTH    1    PLAIN   
service=imap    secured    session=TTm6a5b/swBbtKLu    lip=xxx   
rip=xxx    lport=993    rport=52403
Aug 01 21:30:24 auth: Debug: client passdb out: CONT    1   
Aug 01 21:30:24 auth: Debug: client in: CONT    1    xxxx (previous
base64 data may contain sensitive data)
Aug 01 21:30:24 auth: Debug: cache(info at xxx.com,xxx,<TTm6a5b/swBbtKLu>):
miss
Aug 01 21:30:24 auth: Debug:
passwd-file(info at xxx.com,xxx,<TTm6a5b/swBbtKLu>): lookup:
user=info at xxx.com file=/etc/dovecot/users
Aug 01 21:30:24 auth: Debug: client passdb out: OK    1    user=info at xxx.com
Aug 01 21:30:24 auth: Debug: master in: REQUEST    1973682177    5459   
1    9976303da4c6eb55a008b0cae6ab12a1    session_pid=5462   
request_auth_token
Aug 01 21:30:24 auth: Debug: master userdb out: USER    1973682177   
info at xxx.com    uid=1001    gid=1001    home=/var/vmail/xxx.com/info   
auth_token=31afcf6ff0c5ed5150beb96ad3718cff452badae


The only thing I changed here was the order the passdb backends.

It works fine now, but it not clear to me why the order is so important.
Could somebody explain this? Or is this some bug?

Thanks
Jean-Louis