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

Hi Mark,

when I say AD 2003/8 I mean Active Directory 2003/8.

My configuration is attached.

I based my installation (dovecot+postfix) in the guides of this site: http://www.linuxmail.info

The LDAP part is this: http://www.linuxmail.info/postfix-dovecot-ldap-centos-5/

You can also use PAM to connect to AD (http://www.linuxmail.info/active-directory-dovecot-pam-authentication/) but that way doesn't allow to retrieve custom fields from the AD (ex. a field to set quota per user), so I'm using the standard LDAP method.

Regards

El 10/09/2015 a las 4:51, Mark Foley escribió:

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=

-- Fran Márquez Servicio de Informática - Sistemas y Comunicaciones Confederación Hidrográfica del Guadalquivir Tel.: 955.637.616 E-mail: cumc-4361-2@chguadalquivir.es www.chguadalquivir.es