Hello,
my dovecot installation has been working fine against AD till we upgrade
from AD 2003 to AD 2008. As http://wiki2.dovecot.org/AuthDatabase/LDAP
said, now I'm not able to connect AD through 389 port. The port 3268
works fine though.
(...)
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Error:
master(imap): Auth request timed out (received 0/12 bytes)
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Internal login
failure (pid=4846 id=1) (internal failure, 1 successful auths):
user=<<username>>, method=PLAIN, rip=,
lip=, TLS, session=
(...)
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Error:
ldap(<username>,,<ZjyONSsf6QAKHyZV>): Connection appears
to be hanging, reconnecting
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Error:
ldap(<username>,,): LDAP search returned
multiple entries
(...)
Is there a technical reason for this problem? Does it exist any workaround?
The use of Global Catalog (port 3268) is not a solution for me, since it
misses many attributes. (ex. I use the field "initials" to set the quota
and this field is not available through port 3268).
I also noticed that, now, it uses any DC available in the domain, it
doesn't care what I configured in "hosts = " parameter.
This is using "hosts = dc03.domain:389":
[root@<dovecotServer> ~]# netstat -anp | grep dovecot | grep auth
tcp 22 0 :55217
:389 ESTABLISHED 4872/dovecot/auth
tcp 22 0 :57645
:389 ESTABLISHED 4872/dovecot/auth
tcp 0 0 :55216
:389 ESTABLISHED 4872/dovecot/auth
It looks like it does a look up for other domains controller (I don't
know how nor why) and it connect aleatory to any DC in my domain (in
this case dc06.domain, but it changes any time), additionally to the
configured one (dc03.domain).
This is using "hosts = dc03.domain:3268":
[root@<dovecotServer> ~]# netstat -anp | grep dovecot | grep auth
tcp 0 0 :58485
:3268 ESTABLISHED 4982/dovecot/auth
In this case, only the configured server in host parameter is used (I
think this is the right behaviour)
Aditional info:
CentOS Linux release 7.0.1406 (Core)
dovecot 2.2.10
Build options: ioloop=epoll notify=inotify ipv6 openssl io_block_size=8192
Mail storages: shared mdbox sdbox maildir mbox cydir imapc pop3c raw fail
SQL driver plugins: mysql postgresql sqlite
Passdb: checkpassword ldap pam passwd passwd-file shadow sql
Userdb: checkpassword ldap(plugin) nss passwd prefetch passwd-file sql
My /etc/dovecot/dovecot-ldap.conf.ext
#hosts = dc03.domain:3268
hosts = dc03.domain:389
#uris = ldap://dc03.domain
base = DC=domain
#tls = yes
tls = no
ldap_version = 3
auth_bind = yes
auth_bind_userdn = %u@domain
#auth_bind_userdn = DOMAIN\%u
dn = cn=<user>,cn=Users,dc=domain
dnpass = <password>
#scope = subtree
#deref = never
user_filter =
(&(userPrincipalName=%u@domain)(objectClass=person)(|(mail=%u@<domain>)(othermailbox=%u@<domain>)))
pass_filter =
(&(userPrincipalName=%u@domain)(objectClass=person)(|(mail=%u@<domain>)(othermailbox=%u@<domain>)))
pass_attrs = userPassword=password
user_attrs = Initials=quota_rule=*:storage=%$MB
Log trace using PORT 389:
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x10, ret=1: before/accept initialization []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: before/accept initialization []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client hello A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server hello A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write certificate A []
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: Loading modules
from directory: /usr/lib64/dovecot/auth
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_sqlite.so
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: Loading modules
from directory: /usr/lib64/dovecot/auth
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libauthdb_ldap.so
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: Read auth token
secret from /var/run/dovecot/auth-token-secret.dat
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write key exchange A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server done A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: auth client
connected (pid=4846)
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client key exchange A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read finished A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write session ticket A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write change cipher spec A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write finished A []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x20, ret=1: SSL negotiation finished successfully []
Sep 7 19:00:35 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=1: SSL negotiation finished successfully []
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: client in: AUTH
1 PLAIN service=imap secured session=T+grMCsfqgAKHyZV
lip= rip= lport=993 rport=59818
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: client passdb out:
CONT 1
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: client in: CONT
1 AEN1bWMtNDM2MS0yLXBydWViYQBDb3JyZW9DaGcuMTIzNDU2 (previous
base64 data may contain sensitive data)
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: client passdb out:
OK 1 user=<username>
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug: master in:
REQUEST 4142792705 4846 1
cb2115241ccfd81959c15122ec062a8b session_pid=4849
request_auth_token
Sep 7 19:00:35 <dovecotServer> dovecot: auth: Debug:
ldap(<username>,,): user search:
base=DC=domain scope=subtree
filter=(&(userPrincipalName=<username>@domain)(objectClass=person)(|(mail=<username>@<domain>)(othermailbox=<username>@<domain>)))
fields=Initials
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Error:
master(imap): Auth request timed out (received 0/12 bytes)
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Internal login
failure (pid=4846 id=1) (internal failure, 1 successful auths):
user=<<username>>, method=PLAIN, rip=,
lip=, TLS, session=
Sep 7 19:02:05 <dovecotServer> dovecot: auth: Debug: client in:
CANCEL 1
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL alert:
close notify []
Sep 7 19:02:05 <dovecotServer> dovecot: imap: Error: Login client
disconnected too early
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:02:05 <dovecotServer> dovecot: auth: Debug: auth client
connected (pid=4868)
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x10, ret=1: before/accept initialization []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: before/accept initialization []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client hello A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server hello A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write certificate A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write key exchange A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server done A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client key exchange A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read finished A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write session ticket A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write change cipher spec A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write finished A []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x20, ret=1: SSL negotiation finished successfully []
Sep 7 19:02:05 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=1: SSL negotiation finished successfully []
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Debug: client in: AUTH
1 PLAIN service=imap secured session=ZjyONSsf6QAKHyZV
lip= rip= lport=993 rport=59881
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Debug: client passdb out:
CONT 1
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Debug: client in: CONT
1 AEN1bWMtNDM2MS0yLXBydWViYQBDb3JyZW9DaGcuMTIzNDU2 (previous
base64 data may contain sensitive data)
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Error:
ldap(<username>,,<ZjyONSsf6QAKHyZV>): Connection appears
to be hanging, reconnecting
Sep 7 19:02:06 <dovecotServer> dovecot: auth: Error:
ldap(<username>,,): LDAP search returned
multiple entries
Sep 7 19:03:10 <dovecotServer> dovecot: imap: Error: Auth server
request timed out after 155 secs (client-pid=4846 client-id=1)
Sep 7 19:04:18 <dovecotServer> dovecot: imap-login: Debug: SSL alert:
close notify []
Sep 7 19:04:18 <dovecotServer> dovecot: imap-login: Debug: SSL alert:
close notify []
Sep 7 19:04:36 <dovecotServer> dovecot: auth: Error:
PLAIN(<username>,,<ZjyONSsf6QAKHyZV>): Request 4868.1
timed out after 150 secs, state=1
Sep 7 19:05:05 <dovecotServer> dovecot: imap-login: Disconnected:
Inactivity during authentication (disconnected while authenticating,
waited 179 secs): user=<>, method=PLAIN, rip=,
lip=, TLS, session=<ZjyONSsf6QAKHyZV>
Sep 7 19:05:05 <dovecotServer> dovecot: auth: Debug: client in: CANCEL
Sep 7 19:06:06 <dovecotServer> dovecot: auth:
ldap(<username>,,): Shutting down
Sep 7 19:06:06 <dovecotServer> dovecot: auth: Debug: master userdb out:
FAIL 4142792705
Sep 7 19:06:06 <dovecotServer> dovecot: auth:
ldap(<username>,,<ZjyONSsf6QAKHyZV>): Shutting down
Sep 7 19:06:06 <dovecotServer> dovecot: auth: Debug: client passdb out:
FAIL 1 user=<username> temp
Log trace using PORT 3268:
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
elliptic curve secp384r1 will be used for ECDH and ECDHE key exchanges
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x10, ret=1: before/accept initialization []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: before/accept initialization []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client hello A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server hello A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write certificate A []
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: Loading modules
from directory: /usr/lib64/dovecot/auth
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_sqlite.so
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: Loading modules
from directory: /usr/lib64/dovecot/auth
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libauthdb_ldap.so
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: Read auth token
secret from /var/run/dovecot/auth-token-secret.dat
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write key exchange A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write server done A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=-1: SSLv3 read client certificate A []
Sep 7 19:33:07 <dovecotServer> dovecot: auth: Debug: auth client
connected (pid=4971)
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read client key exchange A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 read finished A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write session ticket A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write change cipher spec A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 write finished A []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2001, ret=1: SSLv3 flush data []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x20, ret=1: SSL negotiation finished successfully []
Sep 7 19:33:07 <dovecotServer> dovecot: imap-login: Debug: SSL:
where=0x2002, ret=1: SSL negotiation finished successfully []
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: client in: AUTH
1 PLAIN service=imap secured session=FAKKpCsf0AAKHyZV
lip= rip= lport=993 rport=61648
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: client passdb out:
CONT 1
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: client in: CONT
1 AEN1bWMtNDM2MS0yAGZvcnRpbmV0LjIwMTQ= (previous base64 data may
contain sensitive data)
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: client passdb out:
OK 1 user=<username>
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: master in:
REQUEST 3261071361 4971 1
4755688f0bdd33a0fadcc5d3b8664e61 session_pid=4974
request_auth_token
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug:
ldap(<username>,,<FAKKpCsf0AAKHyZV>): user search:
base=DC=domain scope=subtree
filter=(&(userPrincipalName=<username>@domain)(objectClass=person)(|(mail=<username>@<domain>)(othermailbox=<username>@<domain>)))
fields=Initials
[Here start the difference between 389 and 3268 ports]
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug:
ldap(<username>,,<FAKKpCsf0AAKHyZV>): no fields returned
by the server
[Next line you can see missing attributes, due to I'm using port 3268]
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug:
ldap(<username>,,<FAKKpCsf0AAKHyZV>): result: Initials
missing
Sep 7 19:33:08 <dovecotServer> dovecot: auth: Debug: master userdb out:
USER 3261071361 <username> uid=1000 gid=1000
home=/home/mailstorage/<domain>/<username>
auth_token=9191cdf475600f0a47e185bb65817c0e0f495894
Sep 7 19:33:08 <dovecotServer> dovecot: imap-login: Login:
user=<<username>>, method=PLAIN, rip=,
lip=, mpid=4974, TLS, session=<FAKKpCsf0AAKHyZV>
Sep 7 19:33:08 <dovecotServer> dovecot: imap: Debug: Loading modules
from directory: /usr/lib64/dovecot
Sep 7 19:33:08 <dovecotServer> dovecot: imap: Debug: Module loaded:
/usr/lib64/dovecot/lib10_quota_plugin.so
Sep 7 19:33:08 <dovecotServer> dovecot: imap: Debug: Module loaded:
/usr/lib64/dovecot/lib11_imap_quota_plugin.so
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug:
Effective uid=1000, gid=1000, home=/home/mailstorage/<domain>/<username>
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug: Quota
root: name=CuotaUsuario backend=maildir args=
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug: Quota
rule: root=CuotaUsuario mailbox=* bytes=2097152 messages=0
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug: Quota
grace: root=CuotaUsuario bytes=209715 (10%)
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug:
Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no,
list=yes, subscriptions=yes location=maildir:~/Maildir
Sep 7 19:33:08 <dovecotServer> dovecot: imap(<username>): Debug:
maildir++: root=/home/mailstorage/<domain>/<username>/Maildir, index=,
indexpvt=, control=,
inbox=/home/mailstorage/<domain>/<username>/Maildir, alt=