Jeroen Scheerder
2014-Feb-27 11:38 UTC
[Dovecot] Dovecot2 vs. AD, "Inactivity during authentication"
Hi,
I'm trying to setup Dovecot2 for
o IMAP client access
o LDA for postfix mail delivery (with SIEVE)
... on a FreeBSD host.
The FreeBSD server has no users (by intention), so I've set up a virtual
mail domain, using LDAP lookups in Postfix. So far so good. Mail delivers into
the proper mailbox.
But I'm stuck getting Dovecot to authenticate. User- and passwd DB's
are set up for LDAP lookups to AD, using an authenticated bind (the AD server
offers no anonymous binds, yet).
I've enabled all the debugging I can find, but my logs have little
information to offer.
Any help in getting me a step further would be much appreciated. In particular,
I'd like to learn how do diagnose these userdb/passdb issues properly.
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
This logging is related to the folloging IMAP session:
ponyboy% telnet localhost 143
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
* OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE
AUTH=PLAIN AUTH=LOGIN] Dovecot ready.
a login js suppressed
* OK Waiting for authentication process to respond..
* BYE Disconnected for inactivity during authentication.
Connection closed by foreign host.
Here's my config:
$ dovecot -n
# 2.2.10: /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 10.0-RELEASE amd64 ufs
auth_debug = yes
auth_mechanisms = plain login
auth_username_format = %Ln
auth_verbose = yes
first_valid_gid = 1000
first_valid_uid = 1000
imap_client_workarounds = delay-newmail
last_valid_gid = 1000
last_valid_uid = 1000
mail_gid = 1000
mail_location = maildir:/var/mail/on2it/%Ln
mail_uid = 1000
maildir_very_dirty_syncs = yes
namespace inbox {
inbox = yes
location mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix }
passdb {
args = /usr/local/etc/dovecot/on2it-ldap-users.cfg
driver = ldap
}
protocols = imap
service auth-worker {
user = root
}
service auth {
unix_listener /var/spool/postfix/private/auth {
mode = 0666
}
unix_listener auth-userdb {
group = postfix
mode = 0666
user = postfix
}
}
service imap-login {
inet_listener imap {
port = 143
}
}
shutdown_clients = no
ssl = no
userdb {
args = /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg
driver = ldap
}
valid_chroot_dirs = /var/mail/on2it
$ cat /usr/local/etc/dovecot/on2it-ldap-users.cfg
hosts = dc2.office.on2it.net
ldap_version = 3
base = dc=office,dc=on2it,dc=net
scope=subtree
auth_bind = yes
dn = [suppressed]
dnpass = [suppressed]
pass_attrs = sAMAccountName=user
user_attrs = \
=home=/var/mail/on2it/%{ldap:sAMAccountName}, \
=mail=maildir:/var/mail/on2it/%{ldap:sAMAccountName}
user_filter = (&(ObjectClass=person)(sAMAccountName=%u))
pass_filter = (&(ObjectClass=person)(sAMAccountName=%u))
iterate_attrs = sAMAccountName=user
iterate_filter = (objectClass=person)
$ ls -l /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg
lrwxr-xr-x 1 root wheel 20 Feb 27 12:07
/usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg -> on2it-ldap-users.cfg
-------------- 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/f1528e50/attachment-0001.sig>
Jeroen Scheerder
2014-Feb-27 11:58 UTC
[Dovecot] Dovecot2 vs. AD, "Inactivity during authentication"
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=1Logging 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: cookieldapsearch -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>
Steffen Kaiser
2014-Feb-28 07:31 UTC
Re: Dovecot2 vs. AD, "Inactivity during authentication"
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Thu, 27 Feb 2014, Jeroen Scheerder wrote:> passdb { > args = /usr/local/etc/dovecot/on2it-ldap-users.cfg > driver = ldap > }> userdb { > args = /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg > driver = ldap > }> $ cat /usr/local/etc/dovecot/on2it-ldap-users.cfg > hosts = dc2.office.on2it.net > ldap_version = 3 > base = dc=office,dc=on2it,dc=net > scope=subtree > auth_bind = yes > dn = [suppressed] > dnpass = [suppressed] > > pass_attrs = sAMAccountName=user > user_attrs = \ > =home=/var/mail/on2it/%{ldap:sAMAccountName}, \ > =mail=maildir:/var/mail/on2it/%{ldap:sAMAccountName}you must not use home dir == mail dir, search list about what wired things can happen, if you do. But this has nothing to do with your auth problem.> user_filter = (&(ObjectClass=person)(sAMAccountName=%u)) > pass_filter = (&(ObjectClass=person)(sAMAccountName=%u)) > > iterate_attrs = sAMAccountName=user > iterate_filter = (objectClass=person) > > $ ls -l /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg > lrwxr-xr-x 1 root wheel 20 Feb 27 12:07 /usr/local/etc/dovecot/on2it-ldap-users-userdb.cfg -> on2it-ldap-users.cfg> 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=jsThis puzzles me, "sAMAccountName unused" should mean that Dovecot does not use the attribute, which contradicts the definition of pass_attrs. Do you have wiered characters in/around the line "pass_attrs = sAMAccountName=user"? Maybe a Windows linebreak ^M / \r or something? A Unicode non-breakable space? Did you stopped, killed any remaining Dovecot processes and restarted Dovecot - just to be sure? Maybe, add sAMAccountName=user to user_attrs, too. - -- Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux) iQEVAwUBUxA7WXD1/YhP6VMHAQKX4ggA1Zn7M3ADyVmqxtYT3aiNW429RiFLnKrX ql8YZUS+ZPAKP7aBzEFZqUFKc3UkP9yR6QfZPoJC/x3DJqnKZZTW6dJl2vDkXVth KUA1OotQVE21E85mbZR8zUYwKGl05saYwJb/4HpfP56xX8PbaItAUPISwPa5LAYK aShfHZ/dD0Qq49eEMqa/ErG/3ntUQfD162UCiKMspUh91i4enEt1WQ2j4cSRN3BV iSwx3U337uFYyUCqAhiUG7dtHU8CH2GD6RNFM/m3JXYZWg91zgKveBNJ4pGzV8mU bb5pJ2KAhUQIjXnCgZrSSVIkgUr6KOMr0gkztACNvwhm78TF45WAbg==Y/0n -----END PGP SIGNATURE-----