[Dovecot] Dovecot2 vs. AD, "Inactivity during authentication"

Fri Feb 28 10:57:22 UTC 2014

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 at .@.....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.. at ...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 at .@.....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..... at ...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 at .@..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
...... at .@.....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.. at .@.....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
...;.. at .@.....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.. at .@.....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
...;.. at .@.....2
.....X...eW.D....._.....
#.RJ.a..0....B.
--- Snip ---