Timo Sirainen wrote:
On to, 2010-06-03 at 09:14 -0600, markham breitbach wrote:
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
Is the above correct? Login shows the username as "bobs", but pop3 sees it as bob_smith@domain? I think that means the passdb lookup did change the username, but a later userdb probably changes it back..
Yes, that's correct.
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.
There shouldn't be any ordering-dependent code..
By changing the order that the objects were requested in the dovecot-ldap.conf I was able to get dovecot to ask for the attributes in the order that they are returned bt the LDAP server, so I think my initail assumption was flawed and it doesn't appear to be related to a difference between the order of the request and the order of the response. Also, by changing the pass_attrs line in dovecot-ldap.conf to:
pass_attrs = uid=user
It looks like dovecot throws a pre-fretch error and then does another query to get the missing parameters. -----snip------ Jun 04 14:22:38 auth(default): Info: prefetch(bobs,192.168.84.12): passdb didn't return userdb entries, trying the next userdb Jun 04 14:22:38 auth(default): Info: ldap(bobs,192.168.84.12): user search: base=dc=2,dc=ssi scope=subtree filter=(&(objectClass=posixAccount)(uid=bobs)) fields=mailQuota,uidNumber,gidNumber
I guess I still need to do some more testing and make sure that solves my problem, but it still looks like there might be a problem with the prefetch.
Logs about broken login with auth_debug=yes might show something useful.
Here is the log with auth_debug=yes and the unmodified pass_attrs config.
Jun 04 10:31:30 auth(default): Info: new auth connection: pid=26207
Jun 04 10:31:49 auth(default): Info: client in: AUTH 1 PLAIN
service=pop3 lip=172.16.129.4 rip=192.168.84.12 lport=110
rport=54955 resp=<hidden>
Jun 04 10:31:49 auth(default): Info:
ldap(bob_smith@example.tld,192.168.84.12): bind search:
base=dc=example,dc=tld
filter=(&(accountstatus=active)(emailaccountStatus=active)(|(uid=bob_smith@example.tld)(mailLocalAddress=bob_smith@example.tld)))
Jun 04 10:31:49 auth(default): Info:
auth(bob_smith@example.tld,192.168.84.12): username changed
bob_smith@example.tld -> bobs
Jun 04 10:31:49 auth(default): Info: ldap(bobs,192.168.84.12): result:
gidNumber(userdb_gid)=2000 uid(user)=bobs uidNumber(userdb_uid)=38538
homeDirectory(userdb_home)=/nonexistent
Jun 04 10:31:49 auth(default): Info: client out: OK 1 user=bobs
Jun 04 10:31:49 auth(default): Info: master in: REQUEST 6 26187 1
Jun 04 10:31:49 auth(default): Info: prefetch(bobs,192.168.84.12): success
Jun 04 10:31:49 auth(default): Info: master out: USER 6
bob_smith@example.tld gid=2000 uid=38538 home=/nonexistent
Jun 04 10:31:49 pop3-login: Info: Login: user=<bobs>, method=PLAIN,
rip=192.168.84.12, lip=172.16.129.4
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Loading modules from
directory: /usr/local/lib/dovecot/pop3
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Module loaded:
/usr/local/lib/dovecot/pop3/lib10_quota_plugin.so
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Effective uid=38538,
gid=2000, home=/nonexistent
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Quota root: name=User
quota backend=maildir args=
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Quota rule: root=User
quota mailbox=* bytes=524288000 messages=0
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Quota rule: root=User
quota mailbox=Trash bytes=52428800 messages=0
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Quota rule: root=User
quota mailbox=Deleted Messages bytes=52428800 messages=0
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: maildir:
data=/var/mail/bob_smith@example.tld
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: maildir++:
root=/var/mail/bob_smith@example.tld, index=, control=,
inbox=/var/mail/bob_smith@example.tld
Jun 04 10:31:49 POP3(bob_smith@example.tld): Info: Namespace : Using
permissions from /var/mail/bob_smith@example.tld: mode=0700 gid=-1
Timo Sirainen wrote:
On to, 2010-06-03 at 09:14 -0600, markham breitbach wrote:
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
Is the above correct? Login shows the username as "bobs", but pop3 sees it as bob_smith@domain? I think that means the passdb lookup did change the username, but a later userdb probably changes it back..
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.
There shouldn't be any ordering-dependent code..
Logs about broken login with auth_debug=yes might show something useful.