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

[Bob Miller]

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