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

[Jeroen Scheerder]

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
-------------- 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/20140227/e09b7ce2/attachment.sig>