[Dovecot] Dovecot2 vs. AD, "Inactivity during authentication"
Hi,
I'm trying to setup Dovecot2 for o IMAP client access o LDA for postfix mail delivery (with SIEVE) ... on a FreeBSD host.
The FreeBSD server has no users (by intention), so I've set up a virtual mail domain, using LDAP lookups in Postfix. So far so good. Mail delivers into the proper mailbox.
But I'm stuck getting Dovecot to authenticate. User- and passwd DB's are set up for LDAP lookups to AD, using an authenticated bind (the AD server offers no anonymous binds, yet). I've enabled all the debugging I can find, but my logs have little information to offer.
Any help in getting me a step further would be much appreciated. In particular, I'd like to learn how do diagnose these userdb/passdb issues properly.
Here's what I see in the logs:
Feb 27 12:25:49 <mail.info> ponyboy dovecot: imap-login: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 172 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<r/ERi2HzQAB/AAAB> Feb 27 12:26:42 <mail.err> ponyboy dovecot: auth: Error: PLAIN(js,127.0.0.1,<r/ERi2HzQAB/AAAB>): Request 74099.1 timed out after 225 secs, state=1
This logging is related to the folloging IMAP session:
ponyboy% telnet localhost 143 Trying 127.0.0.1... Connected to localhost. Escape character is '^]'.
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready. a login js suppressed
- OK Waiting for authentication process to respond..
- BYE Disconnected for inactivity during authentication. Connection closed by foreign host.
Here's my config:
$ dovecot -n
2.2.10: /usr/local/etc/dovecot/dovecot.conf
OS: FreeBSD 10.0-RELEASE amd64 ufs
auth_debug = yes auth_mechanisms = plain login auth_username_format = %Ln auth_verbose = yes first_valid_gid = 1000 first_valid_uid = 1000 imap_client_workarounds = delay-newmail last_valid_gid = 1000 last_valid_uid = 1000 mail_gid = 1000 mail_location = maildir:/var/mail/on2it/%Ln mail_uid = 1000 maildir_very_dirty_syncs = yes namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } passdb { args = /usr/local/etc/dovecot/on2it-ldap-users.cfg driver = ldap } protocols = imap service auth-worker { user = root } service auth { unix_listener /var/spool/postfix/private/auth { mode = 0666 } unix_listener auth-userdb { group = postfix mode = 0666 user = postfix } } service imap-login { inet_listener imap { port = 143 } } shutdown_clients = no ssl = no userdb { args = /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg driver = ldap } valid_chroot_dirs = /var/mail/on2it
$ cat /usr/local/etc/dovecot/on2it-ldap-users.cfg hosts = dc2.office.on2it.net ldap_version = 3 base = dc=office,dc=on2it,dc=net scope=subtree auth_bind = yes dn = [suppressed] dnpass = [suppressed]
pass_attrs = sAMAccountName=user
user_attrs =
=home=/var/mail/on2it/%{ldap:sAMAccountName},
=mail=maildir:/var/mail/on2it/%{ldap:sAMAccountName}
user_filter = (&(ObjectClass=person)(sAMAccountName=%u)) pass_filter = (&(ObjectClass=person)(sAMAccountName=%u))
iterate_attrs = sAMAccountName=user iterate_filter = (objectClass=person)
$ ls -l /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg lrwxr-xr-x 1 root wheel 20 Feb 27 12:07 /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg -> on2it-ldap-users.cfg
Quoth Jeroen Scheerder (27 Feb 2014, 12:38):
Here's what I see in the logs:
Feb 27 12:25:49 <mail.info> ponyboy dovecot: imap-login: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 172 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<r/ERi2HzQAB/AAAB> Feb 27 12:26:42 <mail.err> ponyboy dovecot: auth: Error: PLAIN(js,127.0.0.1,<r/ERi2HzQAB/AAAB>): Request 74099.1 timed out after 225 secs, state=1
Logging to file instead of syslog, I see a bit more:
Feb 27 12:45:27 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Feb 27 12:45:27 auth: Debug: Wrote new auth token secret to /var/run/dovecot/auth-token-secret.dat Feb 27 12:45:27 auth: Debug: auth client connected (pid=74241) Feb 27 12:45:31 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=9QHH22HzYgB/AAAB lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=64354 resp=<hidden> Feb 27 12:45:31 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): bind search: base=dc=office,dc=on2it,dc=net filter=(&(ObjectClass=person)(sAMAccountName=js)) Feb 27 12:48:27 imap-login: Info: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 176 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<9QHH22HzYgB/AAAB> Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js; sAMAccountName unused Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js Feb 27 12:49:16 auth: Error: PLAIN(js,127.0.0.1,<9QHH22HzYgB/AAAB>): Request 74241.1 timed out after 225 secs, state=1 Feb 27 12:49:16 auth: Debug: client in: CANCEL 1 Feb 27 12:49:18 auth: Debug: client passdb out: FAIL 1 user=js temp
Using ldapsearch on this very host, I have verified that this particular ldap query, with the same authenticated bind, actually works:
ponyboy% time ldapsearch -o ldif-wrap=no -x -LLL -E pr=200/noprompt -w suppressed
-H ldap://dc2.office.on2it.net -b dc=office,dc=on2it,dc=net -D suppressed -s sub
'(&(ObjectClass=person)(sAMAccountName=js))' sAMAccountName
dn: CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net
sAMAccountName: js
refldap://DomainDnsZones.office.on2it.net/DC=DomainDnsZones,DC=office,DC=on2it,DC=net
refldap://ForestDnsZones.office.on2it.net/DC=ForestDnsZones,DC=office,DC=on2it,DC=net
refldap://office.on2it.net/CN=Configuration,DC=office,DC=on2it,DC=net
pagedresults: cookie=
ldapsearch -o ldif-wrap=no -x -LLL -E pr=200/noprompt -w [...] -H 0.00s user 0.00s system 19% cpu 0.019 total
Hi,
have you verified from you AD logs that dovecot is sending the same thing as your ldapsearch?
--
Computerisms
Bob Miller
867-334-7117 / 867-633-3760
http://computerisms.ca
On Thu, 2014-02-27 at 12:58 +0100, Jeroen Scheerder wrote:
Quoth Jeroen Scheerder (27 Feb 2014, 12:38):
Here's what I see in the logs:
Feb 27 12:25:49 <mail.info> ponyboy dovecot: imap-login: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 172 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<r/ERi2HzQAB/AAAB> Feb 27 12:26:42 <mail.err> ponyboy dovecot: auth: Error: PLAIN(js,127.0.0.1,<r/ERi2HzQAB/AAAB>): Request 74099.1 timed out after 225 secs, state=1
Logging to file instead of syslog, I see a bit more:
Feb 27 12:45:27 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Feb 27 12:45:27 auth: Debug: Wrote new auth token secret to /var/run/dovecot/auth-token-secret.dat Feb 27 12:45:27 auth: Debug: auth client connected (pid=74241) Feb 27 12:45:31 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=9QHH22HzYgB/AAAB lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=64354 resp=<hidden> Feb 27 12:45:31 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): bind search: base=dc=office,dc=on2it,dc=net filter=(&(ObjectClass=person)(sAMAccountName=js)) Feb 27 12:48:27 imap-login: Info: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 176 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<9QHH22HzYgB/AAAB> Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js; sAMAccountName unused Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js Feb 27 12:49:16 auth: Error: PLAIN(js,127.0.0.1,<9QHH22HzYgB/AAAB>): Request 74241.1 timed out after 225 secs, state=1 Feb 27 12:49:16 auth: Debug: client in: CANCEL 1 Feb 27 12:49:18 auth: Debug: client passdb out: FAIL 1 user=js temp
Using ldapsearch on this very host, I have verified that this particular ldap query, with the same authenticated bind, actually works:
ponyboy% time ldapsearch -o ldif-wrap=no -x -LLL -E pr=200/noprompt -w suppressed
-H ldap://dc2.office.on2it.net -b dc=office,dc=on2it,dc=net -D suppressed -s sub
'(&(ObjectClass=person)(sAMAccountName=js))' sAMAccountName dn: CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net sAMAccountName: jsrefldap://DomainDnsZones.office.on2it.net/DC=DomainDnsZones,DC=office,DC=on2it,DC=net
refldap://ForestDnsZones.office.on2it.net/DC=ForestDnsZones,DC=office,DC=on2it,DC=net
refldap://office.on2it.net/CN=Configuration,DC=office,DC=on2it,DC=net
pagedresults: cookie=
ldapsearch -o ldif-wrap=no -x -LLL -E pr=200/noprompt -w [...] -H 0.00s user 0.00s system 19% cpu 0.019 total
Quoth Bob Miller (27 Feb 2014, 17:58):
have you verified from you AD logs that dovecot is sending the same thing as your ldapsearch?
I have limited access to my AD server. I've verified everything I can using ldapsearch, and I have tcpdump'ed dovecot's LDAP authentication to it. This is what I see:
---- Snip, IMAP user session ---- $ telnet localhost 143 [...]
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready. a1 login js passphrase
- OK Waiting for authentication process to respond..
- BYE Disconnected for inactivity during authentication. Connection closed by foreign host. --- Snip ---
--- Snip, Dovecot log --- Feb 28 11:34:48 auth: Debug: auth client connected (pid=77528) Feb 28 11:34:52 auth: Debug: client in: AUTH 1 PLAIN service=imap secured session=Raj3/HTzkgB/AAAB lip=127.0.0.1 rip=127.0.0.1 lport=143 rport=24210 resp=<hidden> Feb 28 11:34:52 auth: Debug: ldap(js,127.0.0.1,<Raj3/HTzkgB/AAAB>): bind search: base=dc=office,dc=on2it,dc=net filter=(&(objectClass=person)(sAMAccountName=js)) === LONG PAUSE === Feb 28 11:37:48 imap-login: Info: Disconnected: Inactivity during authentication (disconnected while authenticating, waited 176 secs): user=<>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, secured, session=<Raj3/HTzkgB/AAAB> Feb 28 11:38:37 auth: Debug: ldap(js,127.0.0.1,<Raj3/HTzkgB/AAAB>): result: sAMAccountName=js; sAMAccountName unused Feb 28 11:38:37 auth: Debug: ldap(js,127.0.0.1,<Raj3/HTzkgB/AAAB>): result: sAMAccountName=js Feb 28 11:38:37 auth: Error: PLAIN(js,127.0.0.1,<Raj3/HTzkgB/AAAB>): Request 77528.1 timed out after 225 secs, state=1 Feb 28 11:38:37 auth: Debug: client in: CANCEL 1 Feb 28 11:38:39 auth: Debug: client passdb out: FAIL 1 user=js temp --- Snip ---
--- Snip, tcpdump of Dovecot LDAP session (commented, omitting tcp setup/teardown, passphrases replaced ---
Immediately after issuing the IMAP login.
We see the successful bind here
We also see a successful user DN lookup
11:34:52.687896 IP (tos 0x0, ttl 64, id 42561, offset 0, flags [DF], proto TCP (6), length 183) 172.17.50.13.53438 > 172.17.10.2.389: Flags [P.], seq 100:231, ack 23, win 1040, options [nop,nop,TS val 596440913 ecr 123872255], length 131 .....A@.@.....2 .....(......W........... #..Q.b#.0.....`{....eCN=Jabber Server LDAP Koppeling,OU=Service Accounts,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net..passphrase 11:34:52.689710 IP (tos 0x0, ttl 127, id 5023, offset 0, flags [DF], proto TCP (6), length 74) 172.17.10.2.389 > 172.17.50.13.53438: Flags [P.], seq 23:45, ack 231, win 258, options [nop,nop,TS val 123875052 ecr 596440913], length 22 E..J..@...S... .......W(..6....c...... .b..#..Q0........a..... ...... 11:34:52.689816 IP (tos 0x0, ttl 64, id 42564, offset 0, flags [DF], proto TCP (6), length 166) 172.17.50.13.53438 > 172.17.10.2.389: Flags [P.], seq 231:345, ack 45, win 1040, options [nop,nop,TS val 596440913 ecr 123875052], length 114 .....D@.@.....2 .....(..6...m........... #..Q.b..0p...ck..dc=office,dc=on2it,dc=net .. ............-....objectClass..person....sAMAccountName..js0...sAMAccountName 11:34:52.690695 IP (tos 0x0, ttl 127, id 5024, offset 0, flags [DF], proto TCP (6), length 488) 172.17.10.2.389 > 172.17.50.13.53438: Flags [P.], seq 45:481, ack 345, win 258, options [nop,nop,TS val 123875053 ecr 596440913], length 436 E.....@...R>.. .......m(.............. .b..#..Q0........d....v.NCN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net0.... 0.......sAMAccountName1.......js0....]...s....T.Rldap://DomainDnsZones.office.on2it.net/DC=DomainDnsZones,DC=office,DC=on2it,DC=net0....]...s....T.Rldap://ForestDnsZones.office.on2it.net/DC=ForestDnsZones,DC=office,DC=on2it,DC=net0....M...s....D.Bldap://office.on2it.net/CN=Configuration,DC=office,DC=on2it,DC=net0........e..... ......
We've obtained the expected result from our query.
=== Pause, and we get the "OK Waiting for authentication process to respond.." response in sync with... === 11:34:52.784578 IP (tos 0x0, ttl 64, id 42568, offset 0, flags [DF], proto TCP (6), length 52) 172.17.50.13.53438 > 172.17.10.2.389: Flags [.], seq 345, ack 481, win 1037, options [nop,nop,TS val 596441011 ecr 123875053], length 0 ...4.H@.@..J..2 .X..........!... #....b.. === LONG PAUSE ===
Then 1m45s after authentication, we *do* see the expected LDAP auth
attempt ("finally")
Why the delay?
11:38:37.825390 IP (tos 0x0, ttl 64, id 42651, offset 0, flags [DF], proto TCP (6), length 152) 172.17.50.13.53438 > 172.17.10.2.389: Flags [P.], seq 345:445, ack 481, win 1040, options [nop,nop,TS val 596666051 ecr 123875053], length 100 ......@.@.....2 .....(......!........... #.f..b..0b...`]....NCN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net..passphrase 11:38:37.827354 IP (tos 0x0, ttl 127, id 9765, offset 0, flags [DF], proto TCP (6), length 74) 172.17.10.2.389 > 172.17.50.13.53438: Flags [P.], seq 481:503, ack 445, win 258, options [nop,nop,TS val 123897567 ecr 596666051], length 22 E..J&%@...AW.. .......!(.............. .b..#.f.0........a..... ...... 11:38:37.924458 IP (tos 0x0, ttl 64, id 42653, offset 0, flags [DF], proto TCP (6), length 52) 172.17.50.13.53438 > 172.17.10.2.389: Flags [.], seq 445, ack 503, win 1040, options [nop,nop,TS val 596666151 ecr 123897567], length 0 ...4..@.@.....2 .....(......7.....X..... #.g'.b.. 11:39:38.119947 IP (tos 0x0, ttl 64, id 42656, offset 0, flags [DF], proto TCP (6), length 59) 172.17.50.13.53438 > 172.17.10.2.389: Flags [P.], seq 445:452, ack 503, win 1040, options [nop,nop,TS val 596726346 ecr 123897567], length 7 ...;..@.@.....2 .....(......7....._..... B.RJ.b..0... 11:39:38.120029 IP (tos 0x0, ttl 64, id 42657, offset 0, flags [DF], proto TCP (6), length 52) 172.17.50.13.53438 > 172.17.10.2.389: Flags [F.], seq 452, ack 503, win 1040, options [nop,nop,TS val 596726346 ecr 123897567], length 0 ...4..@.@.....2 .....(......7.....X..... #.RJ.b.. 11:39:38.120173 IP (tos 0x0, ttl 64, id 42658, offset 0, flags [DF], proto TCP (6), length 59) 172.17.50.13.64429 > 172.17.10.2.389: Flags [P.], seq 1491639458:1491639465, ack 1700255044, win 1040, options [nop,nop,TS val 596726346 ecr 123849133], length 7 ...;..@.@.....2 .....X...eW.D....._..... #.RJ.a..0....B. --- Snip ---
Quoth Jeroen Scheerder (28 Feb 2014, 11:57):
tcpdump of Dovecot LDAP session
I've since captured to a file, and used wireshark to get a bit more grasp on the LDAP transactions:
js@tchotchke:s003(31) tshark -o tcp.check_checksum:FALSE -ta -r Downloads/dc2.pcap 1 13:14:37.274193 172.17.50.13 -> 172.17.10.2 LDAP 197 bindRequest(7) "CN=Jabber Server LDAP Koppeling,OU=Service Accounts,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" simple 2 13:14:37.276072 172.17.10.2 -> 172.17.50.13 LDAP 88 bindResponse(7) success 3 13:14:37.276160 172.17.50.13 -> 172.17.10.2 LDAP 180 searchRequest(8) "dc=office,dc=on2it,dc=net" wholeSubtree 4 13:14:37.276965 172.17.10.2 -> 172.17.50.13 LDAP 502 searchResEntry(8) "CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" | searchResRef(8) | searchResRef(8) | searchResRef(8) | searchResDone(8) success 5 13:14:37.372560 172.17.50.13 -> 172.17.10.2 TCP 66 49416 > 389 [ACK] Seq=246 Ack=459 Win=1037 Len=0 TSval=602425599 TSecr=124473537 6 13:18:22.424078 172.17.50.13 -> 172.17.10.2 LDAP 166 bindRequest(12) "CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" simple 7 13:18:22.426516 172.17.10.2 -> 172.17.50.13 LDAP 88 bindResponse(12) success
So from the looks of it all is hunky-dory, LDAP-wise.
- An authenticated bind (using a service account) as intended is done in frame 1
- Successfully, frame 2 indicates
- The DN is searched successfully (frames 3, 4)
- Frame 5 (length 0) is some kind of TCP keepalive, performed by the LDAP client library, or so I suspect
- Then we have a succesful bind to the user DN (as obtained in frame 4), we see this in frames 6 and 7
- But frames 6 and 7 occur after a long, long delay, as shown with relative timing:
js@tchotchke:s003(32) tshark -o tcp.check_checksum:FALSE -tr -r Downloads/dc2.pcap 1 0.000000 172.17.50.13 -> 172.17.10.2 LDAP 197 bindRequest(7) "CN=Jabber Server LDAP Koppeling,OU=Service Accounts,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" simple 2 0.001879 172.17.10.2 -> 172.17.50.13 LDAP 88 bindResponse(7) success 3 0.001967 172.17.50.13 -> 172.17.10.2 LDAP 180 searchRequest(8) "dc=office,dc=on2it,dc=net" wholeSubtree 4 0.002772 172.17.10.2 -> 172.17.50.13 LDAP 502 searchResEntry(8) "CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" | searchResRef(8) | searchResRef(8) | searchResRef(8) | searchResDone(8) success 5 0.098367 172.17.50.13 -> 172.17.10.2 TCP 66 49416 > 389 [ACK] Seq=246 Ack=459 Win=1037 Len=0 TSval=602425599 TSecr=124473537 6 225.149885 172.17.50.13 -> 172.17.10.2 LDAP 166 bindRequest(12) "CN=Jeroen Scheerder,OU=Users,OU=Netherlands,OU=ON2IT,DC=office,DC=on2it,DC=net" simple 7 225.152323 172.17.10.2 -> 172.17.50.13 LDAP 88 bindResponse(12) success
I think it's just weird, and I'm beginning to guess a little source dive will do me some good. :-)
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Thu, 27 Feb 2014, Jeroen Scheerder wrote:
passdb { args = /usr/local/etc/dovecot/on2it-ldap-users.cfg driver = ldap }
userdb { args = /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg driver = ldap }
$ cat /usr/local/etc/dovecot/on2it-ldap-users.cfg hosts = dc2.office.on2it.net ldap_version = 3 base = dc=office,dc=on2it,dc=net scope=subtree auth_bind = yes dn = [suppressed] dnpass = [suppressed]
pass_attrs = sAMAccountName=user user_attrs =
=home=/var/mail/on2it/%{ldap:sAMAccountName},
=mail=maildir:/var/mail/on2it/%{ldap:sAMAccountName}
you must not use home dir == mail dir, search list about what wired things can happen, if you do. But this has nothing to do with your auth problem.
user_filter = (&(ObjectClass=person)(sAMAccountName=%u)) pass_filter = (&(ObjectClass=person)(sAMAccountName=%u))
iterate_attrs = sAMAccountName=user iterate_filter = (objectClass=person)
$ ls -l /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg lrwxr-xr-x 1 root wheel 20 Feb 27 12:07 /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg -> on2it-ldap-users.cfg
Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js; sAMAccountName unused Feb 27 12:49:16 auth: Debug: ldap(js,127.0.0.1,<9QHH22HzYgB/AAAB>): result: sAMAccountName=js
This puzzles me, "sAMAccountName unused" should mean that Dovecot does not use the attribute, which contradicts the definition of pass_attrs. Do you have wiered characters in/around the line "pass_attrs = sAMAccountName=user"? Maybe a Windows linebreak ^M / \r or something? A Unicode non-breakable space? Did you stopped, killed any remaining Dovecot processes and restarted Dovecot - just to be sure?
Maybe, add sAMAccountName=user to user_attrs, too.
Steffen Kaiser
-----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBUxA7WXD1/YhP6VMHAQKX4ggA1Zn7M3ADyVmqxtYT3aiNW429RiFLnKrX ql8YZUS+ZPAKP7aBzEFZqUFKc3UkP9yR6QfZPoJC/x3DJqnKZZTW6dJl2vDkXVth KUA1OotQVE21E85mbZR8zUYwKGl05saYwJb/4HpfP56xX8PbaItAUPISwPa5LAYK aShfHZ/dD0Qq49eEMqa/ErG/3ntUQfD162UCiKMspUh91i4enEt1WQ2j4cSRN3BV iSwx3U337uFYyUCqAhiUG7dtHU8CH2GD6RNFM/m3JXYZWg91zgKveBNJ4pGzV8mU bb5pJ2KAhUQIjXnCgZrSSVIkgUr6KOMr0gkztACNvwhm78TF45WAbg== =Y/0n -----END PGP SIGNATURE-----
participants (3)
-
Bob Miller
-
Jeroen Scheerder
-
Steffen Kaiser