I have setup dovecot to allow users to login using their email address or uid and have found a strange behaviour when the user logs in using the email address for a "username". I am using OpenLDAP for a backend data store with a rather customized schema. This behaviour occurs for both POP3 and IMAP logins. For some users it works as expected, but for others the pass_attrs->user does not get mapped back to the uid, but remains the mailLocalAddress (dovecot-ldap.conf is attached at the end of this post).
Here is an excerpt from the logs for a working and a malfunctioning user. In both cases the users were logged directly into the pop3 port (ie. telnet <mailserver> 110) and used the fully qualified email address as the user (ie. foo@ex.tld).
Jun 02 13:23:19 pop3-login: Info: Login: user=<foo>, method=PLAIN, rip=64.247.129.10, lip=64.247.129.10, secured Jun 02 13:23:19 POP3(foo): Info: Loading modules from directory: /usr/local/lib/dovecot/pop3 Jun 02 13:23:19 POP3(foo): Info: Module loaded: /usr/local/lib/dovecot/pop3/lib10_quota_plugin.so Jun 02 13:23:19 POP3(foo): Info: Effective uid=14921, gid=2000, home=/nonexistent Jun 02 13:23:19 POP3(foo): Info: Quota root: name=User quota backend=maildir args= Jun 02 13:23:19 POP3(foo): Info: Quota rule: root=User quota mailbox=* bytes=0 messages=0 Jun 02 13:23:19 POP3(foo): Info: maildir: data=/var/mail/foo Jun 02 13:23:19 POP3(foo): Info: maildir++: root=/var/mail/foo, index=, control=, inbox=/var/mail/foo Jun 02 13:23:19 POP3(foo): Info: Namespace : Using permissions from /var/mail/foo: mode=0700 gid=-1
Jun 02 16:54:06 pop3-login: Info: Login: user=<bobs>, method=PLAIN, rip=199.247.84.12, lip=64.247.129.4 Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Loading modules from directory: /usr/local/lib/dovecot/pop3 Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Module loaded: /usr/local/lib/dovecot/pop3/lib10_quota_plugin.so Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Effective uid=38538, gid=2000, home=/nonexistent Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Quota root: name=User quota backend=maildir args= Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Quota rule: root=User quota mailbox=* bytes=524288000 messages=0 Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Quota rule: root=User quota mailbox=Trash bytes=52428800 messages=0 Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Quota rule: root=User quota mailbox=Deleted Messages bytes=52428800 messages=0 Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: maildir: data=/var/mail/bob_smith@example.tld Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: maildir++: root=/var/mail/bob_smith@example.tld, index=, control=, inbox=/var/mail/bob_smith@example.tld Jun 02 16:54:06 POP3(bob_smith@example.tld): Info: Namespace : Using permissions from /var/mail/bob_smith@example.tld: mode=0700 gid=-1 Jun 02 16:54:10 POP3(bob_smith@example.tld): Info: Disconnected: Logged out top=0/0, retr=0/0, del=0/0, size=0
After much searching for anything different between these records, some tcpdumps showed that the problem occured when LDAP returned the attributes in a different order than they are requested in.
In this sample, you can see the request for uid,homeDirectory,uidNumber,gidNumber,mailQuota and the values are returned in the order gidNumber, uid, uidNumber, homeDirectory. There is no mailQuota set for this user.
16:54:06.145597 IP mail.xxxxx.com.62929 > closest-ldap.ldap: P 14:261(247) ack 15 win 33304 <nop,nop,timestamp 1521221146 267819447> 0x0000: 4500 012b fd4d 4000 4006 b87a 40f7 8104 E..+.M@.@..z@... 0x0010: 40f7 8112 f5d1 0185 41e1 8b7d 5aea 01d9 @.......A..}Z... 0x0020: 8018 8218 8522 0000 0101 080a 5aab fe1a ....."......Z... 0x0030: 0ff6 99b7 3081 f402 0120 6381 ee04 0b64 ....0.....c....d 0x0040: 633d 322c 6463 3d73 7369 0a01 020a 0100 c=2,dc=ssi...... 0x0050: 0201 0002 0100 0101 00a0 8198 a317 040d ................ 0x0060: 6163 636f 756e 7473 7461 7475 7304 0661 accountstatus..a 0x0070: 6374 6976 65a3 1c04 1265 6d61 696c 6163 ctive....emailac 0x0080: 636f 756e 7453 7461 7475 7304 0661 6374 countStatus..act 0x0090: 6976 65a1 5fa3 2704 0375 6964 0420 626f ive._.'..uid..bo 0x00a0: 625f 6d61 6364 6f6e 616c 6440 6772 6561 b_xxxxxxxxx@xxxx 0x00b0: 7473 6c61 7665 6865 6c69 2e63 6f6d a334 xxxxxxxxxx.com.4 0x00c0: 0410 6d61 696c 4c6f 6361 6c41 6464 7265 ..mailLocalAddre 0x00d0: 7373 0420 626f 625f 6d61 6364 6f6e 616c ss..bob_xxxxxxxx 0x00e0: 6440 6772 6561 7473 6c61 7665 6865 6c69 x@xxxxxxxxxxxxxx 0x00f0: 2e63 6f6d 3035 0403 7569 6404 0d68 6f6d .com05..uid..hom 0x0100: 6544 6972 6563 746f 7279 0409 7569 644e eDirectory..uidN 0x0110: 756d 6265 7204 0967 6964 4e75 6d62 6572 umber..gidNumber 0x0120: 0409 6d61 696c 5175 6f74 61 ..mailQuota 16:54:06.147464 IP closest-ldap.ldap > mail.xxxxx.com.62929: P 15:142(127) ack 261 win 32942 <nop,nop,timestamp 267819449 1521221146> 0x0000: 4500 00b3 bb91 4000 4006 faae 40f7 8112 E.....@.@...@... 0x0010: 40f7 8104 0185 f5d1 5aea 01d9 41e1 8c74 @.......Z...A..t 0x0020: 8018 80ae b708 0000 0101 080a 0ff6 99b9 ................ 0x0030: 5aab fe1a 307d 0201 2064 7804 1663 6e3d Z...0}...dx..cn= 0x0040: 6773 6862 6f62 6d2c 6463 3d32 2c64 633d xxxbobx,dc=2,dc= 0x0050: 7373 6930 5e30 1304 0967 6964 4e75 6d62 ssi0^0...gidNumb 0x0060: 6572 3106 0404 3230 3030 3010 0403 7569 er1...20000...ui 0x0070: 6431 0904 0767 7368 626f 626d 3014 0409 d1...xxxbobx0... 0x0080: 7569 644e 756d 6265 7231 0704 0533 3835 uidNumber1...385 0x0090: 3338 301f 040d 686f 6d65 4469 7265 6374 380...homeDirect 0x00a0: 6f72 7931 0e04 0c2f 6e6f 6e65 7869 7374 ory1.../nonexist 0x00b0: 656e 74 ent
I will spare you the packet dump, but in the cases where the login works correctly, LDAP returns the values in the same order that they are requested in. This behaviour has been found with both OpenLDAP: slapd 2.3.39 and OpenLDAP: slapd 2.4.17, and is consistent with standard LDAP behaviour (ie, there is no guaranteed ordering in the LDAP database).
A brief look at the code, seems to indicate that the values are being pulled from the LDAP return struct in a step-wise manner, which could certainly put them out of sync with the request if it is assumed that they will always be returned in the same order....This is just based on a quick review of the code though, and not any detailed tracing.
Here is the obligatory dovecot -n:
# 1.2.11: /usr/local/etc/dovecot.conf # OS: FreeBSD 6.4-RELEASE-p7 i386 nullfs log_path: /var/log/dovecot.log info_log_path: /var/log/dovecot-info.log protocols: pop3 pop3s imap imaps disable_plaintext_auth: no login_dir: /usr/local/var/run/dovecot/login login_executable(default): /usr/local/libexec/dovecot/imap-login login_executable(imap): /usr/local/libexec/dovecot/imap-login login_executable(pop3): /usr/local/libexec/dovecot/pop3-login first_valid_uid: 0 mail_location: maildir:/var/mail/%u mail_debug: yes mail_executable(default): /usr/local/libexec/dovecot/imap mail_executable(imap): /usr/local/libexec/dovecot/imap mail_executable(pop3): /usr/local/libexec/dovecot/pop3 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(pop3): quota mail_plugin_dir(default): /usr/local/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3 pop3_uidl_format(default): %08Xu%08Xv pop3_uidl_format(imap): %08Xu%08Xv pop3_uidl_format(pop3): %v.%u lda: postmaster_address: postmaster@ssimicro.com mail_plugins: quota log_path: info_log_path: auth default: passdb: driver: ldap args: /usr/local/etc/dovecot-ldap.conf userdb: driver: prefetch userdb: driver: ldap args: /usr/local/etc/dovecot-ldap.conf userdb: driver: passwd socket: type: listen master: path: /usr/local/var/run/dovecot/auth-master mode: 384 user: dovecot plugin: quota: maildir:User quota quota_rule: *:storage=500MB quota_rule2: Trash:storage=50MB quota_rule3: Deleted Messages:storage=50MB home: /tmp/thome
and the dovecot-ldap.conf
hosts = closest-ldap base = "dc=2,dc=ssi" scope = subtree auth_bind = yes pass_attrs = uid=user, homeDirectory=userdb_home,uidNumber=userdb_uid,gidNumber=userdb_gid,mailQuota=userdb_quota_rule=*:bytes=%$ user_attrs = mailQuota=quota_rule=*:bytes=%$, uidNumber=uid,gidNumber=gid pass_filter = (&(accountstatus=active)(emailaccountStatus=active)(|(uid=%u)(mailLocalAddress=%u)))