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

[Jeroen Scheerder]

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 at 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 at 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. :-)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 881 bytes
Desc: OpenPGP digital signature
URL: <http://dovecot.org/pipermail/dovecot/attachments/20140228/67236ab2/attachment.sig>