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=

Hi Matthias,

thank you very much! that fixed the problem.

I had workaround the problem by using "base = ou=xxxx, dc=dom", instead of "base = dc=dom" in the dovecot-ldap.conf.ext file, because that also worked (I don't know why, but the problem happen if you use as base just the domain, but not if you add a second level). But that forced to me to use several userdb/passdb blocks definitions, one for each OU in which I have users, so I think that your fix is better.

I'm not able to understand the actual reason behind all this though...

What's the technical explanation behind this behaviour?? I mean, it seems to be that the problem is that the Domain controller (DC) was sending a "referrals" answer and dovecot auth made a connection to these others DC but something wrong happened (dovecot can't deal correctly with that kind of answers?? I don't know).

Anyways, as far as I know:

1. A referral answer should be done by a DC when it can't provide the object that the client are requesting
2. REFERRALS off in ldap.conf means that the client should not follow referrals returned by the DC

So, if a referral answer is given from my DC, I think that is because such DC can't provide the object which the client is looking for, so, why works fine just by telling dovecot: "Don't follow referrals"?

Regards

El 09/09/2015 a las 17:22, Matthias Lay escribió:

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=

Thank again for the solution and for the explanation.

Fran

El 10/09/2015 a las 15:40, Matthias Lay escribió:

Hi Fran,

this is not a dovecot problem, thats a pure dns problem and can only be fixed in your dns environment.

referrals are propagated in a "special" dns design in SRV records. so the ldap client performs a dns lookup for this names and this is the point of hanging (as in most "hanging cases", its dns).

see: https://technet.microsoft.com/en-us/library/cc978014.aspx https://technet.microsoft.com/en-us/library/cc961719.aspx http://www.mail-archive.com/cas@tp.its.yale.edu/msg00797.html

for information.

Greetz Matze

On Thu, 10 Sep 2015 13:10:57 +0200 Fran cumc-4361-2@chguadalquivir.es wrote:

...

Hi Matthias,

thank you very much! that fixed the problem.

I had workaround the problem by using "base = ou=xxxx, dc=dom", instead of "base = dc=dom" in the dovecot-ldap.conf.ext file, because that also worked (I don't know why, but the problem happen if you use as base just the domain, but not if you add a second level). But that forced to me to use several userdb/passdb blocks definitions, one for each OU in which I have users, so I think that your fix is better.

I'm not able to understand the actual reason behind all this though...

What's the technical explanation behind this behaviour?? I mean, it seems to be that the problem is that the Domain controller (DC) was sending a "referrals" answer and dovecot auth made a connection to these others DC but something wrong happened (dovecot can't deal correctly with that kind of answers?? I don't know).

Anyways, as far as I know:

1. A referral answer should be done by a DC when it can't provide the object that the client are requesting
2. REFERRALS off in ldap.conf means that the client should not follow referrals returned by the DC

So, if a referral answer is given from my DC, I think that is because such DC can't provide the object which the client is looking for, so, why works fine just by telling dovecot: "Don't follow referrals"?

Regards

El 09/09/2015 a las 17:22, Matthias Lay escribió:

...

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