Re: My dovecot works fine against Active Directory 2003, but not against AD2008

10 Sep 2015

      Fran and/or Matthias,
Could you publish your doveconf -n? I can't get dovecot to authenticate with my
AD. Maybe you have a solution I could try.
What mail client(s) are you using? I assume by "AD 2003/8" You mean SBS2003/8
and are therefore using Outlook?
--Mark
-----Original Message-----
...
Date: Wed, 9 Sep 2015 17:22:34 +0200
From: Matthias Lay matthias.lay@securepoint.de
To: Dovecot Mailing List dovecot@dovecot.org
Subject: Re: My dovecot works fine against Active Directory 2003, but not
against AD2008
hi,
check your
/etc/openldap/ldap.conf
for
REFERRALS off
I had this errors with "referrals on" in misconfigured dns environments.
you can debug the dns packets by strace-ing the auth process
On Tue, 8 Sep 2015 11:00:37 +0200
Fran cumc-4361-2@chguadalquivir.es wrote:
...
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=

Re: My dovecot works fine against Active Directory 2003, but not against AD2008

Mark Foley

This is using "hosts = dc03.domain:389":

This is using "hosts = dc03.domain:3268":

Aditional info:

My /etc/dovecot/dovecot-ldap.conf.ext

Log trace using PORT 389:

Log trace using PORT 3268: