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,
--- 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 ---