[Dovecot] mangled user_attrs from LDAP

[markham breitbach]

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 at 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 at 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 at example.tld,192.168.84.12): bind search:
base=dc=example,dc=tld
filter=(&(accountstatus=active)(emailaccountStatus=active)(|(uid=bob_smith at example.tld)(mailLocalAddress=bob_smith at example.tld)))
Jun 04 10:31:49 auth(default): Info:
auth(bob_smith at example.tld,192.168.84.12): username changed
bob_smith at 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 at 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 at example.tld): Info: Loading modules from
directory: /usr/local/lib/dovecot/pop3
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Module loaded:
/usr/local/lib/dovecot/pop3/lib10_quota_plugin.so
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Effective uid=38538,
gid=2000, home=/nonexistent
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Quota root: name=User
quota backend=maildir args=
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Quota rule: root=User
quota mailbox=* bytes=524288000 messages=0
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Quota rule: root=User
quota mailbox=Trash bytes=52428800 messages=0
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Quota rule: root=User
quota mailbox=Deleted Messages bytes=52428800 messages=0
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: maildir:
data=/var/mail/bob_smith at example.tld
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: maildir++:
root=/var/mail/bob_smith at example.tld, index=, control=,
inbox=/var/mail/bob_smith at example.tld
Jun 04 10:31:49 POP3(bob_smith at example.tld): Info: Namespace : Using
permissions from /var/mail/bob_smith at 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 at 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 at 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.
>
>