[Dovecot] LDAP auth_bind hangs and times out

Jack McKinney

3 Apr 2008 3 Apr '08

5:46 p.m.

I have _almost_ got Dovecot working!  One little snag...

My users login using their email address as username. Each domain has

their own LDAP subtree. Each user has an entry in the ou=users subtree of the domain subtree, and has a mail: field (inetOrgPerson) listing their email address/login name. I am trying to use auth_bind: when I login with jackmc@lorentz.com, dovecot should search for mail=jackmc@lorentz.com in the onelevel below ou=users,dc=lorentz,dc=com and find me as "cn=Jack McKinney,ou=users,dc=lorentz,dc=com". I have created an entry in LDAP (varmail) that should be able to do this query. Indeed, from the command line, it works:

ldapsearch -h ldap.lrtz -b 'ou=users, dc=lorentz, dc=com' -D 'cn=varmail,ou=users,dc=lorentz,dc=com' -x -W -s onelevel '(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))' Enter LDAP Password: # extended LDIF # # LDAPv3 # base with scope oneLevel # filter: (&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com)) # requesting: ALL #

# Jack McKinney, users, lorentz.com dn: cn=Jack McKinney,ou=users,dc=lorentz,dc=com objectClass: top objectClass: person objectClass: organizationalPerson objectClass: inetOrgPerson cn: Jack McKinney givenName: Jack McKinney sn: McKinney mail: jackmc@lorentz.com

# search result search: 2 result: 0 Success

# numResponses: 2 # numEntries: 1

' However, it appears that dovecot performs the above query successfully, but then never uses the password and retrieved DN to attempt to bind and authenticate the user. Instead, it just times out.

My dovecot-ldap.conf is:

hosts = ldap.lrtz dn = cn=varmail,ou=users,dc=lorentz,dc=com dnpass = ********* ldap_version = 3 auth_bind = yes pass_filter = (&(objectClass=inetOrgPerson)(mail=%Lu)) base = ou=users, dc=%Dd scope = onelevel

The dovecot log shows:

Apr 3 08:13:21 fourier dovecot: auth(default): new auth connection: pid=15774 Apr 3 08:13:30 fourier dovecot: auth(default): client in: AUTH^I1^IPLAIN^Iservice=IMAP^Isecured^Ilip=x.x.x.x^Irip=y.y.y.y^Iresp=<hidden> Apr 3 08:13:30 fourier dovecot: auth(default): ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com)) Apr 3 08:16:30 fourier dovecot: imap-login: Disconnected: Inactivity: method=PLAIN, rip=y.y.y.y, lip=x.x.x.x, TLS

The OpenLDAP log shows that the query is received and that it returns a

match:

Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SRCH base="ou=users,dc=lorentz,dc=com" scope=1 deref=0 filter="(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))" Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SRCH attr=uid Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT tag=101 err=0 nentries=1 text=

When I do the query from the command line, there is an additional pair

of lines:

Apr 3 08:18:10 fourier slapd[16106]: conn=22 op=2 UNBIND Apr 3 08:18:10 fourier slapd[16106]: conn=22 fd=28 closed

I thus conclude that Dovecot is not closing the connection.

-- Jack McKinney GPG 1024D/99C6A174 jackmc@lorentz.com YM:lfaatsnat2006 AIM:jackmclorentz "There is no parameter that makes it impossible for you to perform still more excellently." -Mario Cuomo, on the lack of a clock in baseball

Attachments:

signature.asc (application/pgp-signature — 189 bytes)

Show replies by date

Timo Sirainen

3 Apr 3 Apr

11:43 p.m.

On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...

I have _almost_ got Dovecot working! One little snag...

What version?

Jack McKinney

11:46 p.m.

Red Hat Linux release 7.2 (Enigma) OpenLDAP 2.3.38 Dovecot 1.0.12

On Thu, 2008-04-03 at 23:43 +0300, Timo Sirainen wrote:

...

On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...
I have _almost_ got Dovecot working! One little snag...

What version?

Timo Sirainen

11:59 p.m.

On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...

ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))

Here should be a line saying "result: <returned fields>". Since there isn't, Dovecot never appears to receive the reply. You could verify this by adding to src/auth/db-ldap.c ldap_input() around line 372:

	msgid = ldap_msgid(res);

// added line: i_info("LDAP: Received reply %d", msgid);

msgid might be the same as this tag:

...

Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT tag=101

But I'm not sure. If you anyway receive a reply after the "bind search", there's something wrong in Dovecot's error handling.

Jack McKinney

4 Apr 4 Apr

12:06 a.m.

I am not sure that I understand you, here. Are you saying that I am

missing something from my configuration after the "filter=" line like a pass_attrs listing fields to return? I do not have one, as there are no fields that I need returned. The only thing that dovecot needs is the DN of the match itself.

According to http://wiki.dovecot.org/AuthDatabase/LDAP ,

"The pass_filter is used to find the LDAP entry, and the DN is taken from the reply."

Should I add a dummy pass_attrs entry?  What field is safe to grab?

E.g., I do not want to overwrite "user"...

On Thu, 2008-04-03 at 23:59 +0300, Timo Sirainen wrote:

...

On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...
ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))

Here should be a line saying "result: <returned fields>". Since there isn't, Dovecot never appears to receive the reply. You could verify this by adding to src/auth/db-ldap.c ldap_input() around line 372:
  msgid = ldap_msgid(res);
// added line: i_info("LDAP: Received reply %d", msgid);

msgid might be the same as this tag:

...
Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT tag=101

But I'm not sure. If you anyway receive a reply after the "bind search", there's something wrong in Dovecot's error handling.

Timo Sirainen

12:11 a.m.

No, I mean this appears to be a bug somewhere since a LDAP request is
sent, but it's never received by Dovecot. So either Dovecot does
something wrong, OpenLDAP library does something wrong or your network
blocks the reply for some reason. For example on my system:

auth(default): ldap(foo,127.0.0.1): bind search: base=... auth(default): ldap(foo,127.0.0.1): result: uid(user)=foo

If Dovecot receives a reply to the "bind search", it logs the "result"
line, which your logs show is missing.

On Apr 4, 2008, at 12:06 AM, Jack McKinney wrote:

...

I am not sure that I understand you, here. Are you saying that I am missing something from my configuration after the "filter=" line
like a pass_attrs listing fields to return? I do not have one, as there
are no fields that I need returned. The only thing that dovecot needs is the DN of the match itself.

According to http://wiki.dovecot.org/AuthDatabase/LDAP ,

"The pass_filter is used to find the LDAP entry, and the DN is taken from the reply."

Should I add a dummy pass_attrs entry? What field is safe to grab? E.g., I do not want to overwrite "user"...

On Thu, 2008-04-03 at 23:59 +0300, Timo Sirainen wrote:

...
On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...
ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))

Here should be a line saying "result: <returned fields>". Since there isn't, Dovecot never appears to receive the reply. You could verify
this by adding to src/auth/db-ldap.c ldap_input() around line 372:
  msgid = ldap_msgid(res);
// added line: i_info("LDAP: Received reply %d", msgid);

msgid might be the same as this tag:

...
Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT
tag=101

But I'm not sure. If you anyway receive a reply after the "bind
search", there's something wrong in Dovecot's error handling.
-- Jack McKinney GPG 1024D/99C6A174 jackmc@lorentz.com YM:lfaatsnat2006 AIM:jackmclorentz "There is no parameter that makes it impossible for you to perform
still more excellently." -Mario Cuomo, on the lack of a clock in baseball

Jack McKinney

12:28 a.m.

I added the i_info line below and copied over the new dovecot-auth. It

is hanging at the same place; the "LDAP: Received reply" line is not in the log. Again, exactly 180 seconds after the last log entry, the connection drops. However, that line _does_ appear in the log back at startup...

Apr 3 15:19:05 fourier dovecot: Dovecot v1.0.12 starting up Apr 3 15:19:05 fourier dovecot: auth(default): LDAP: Received reply 1 Apr 3 15:19:06 fourier dovecot: auth(default): new auth connection: pid=30934 Apr 3 15:19:06 fourier dovecot: auth(default): new auth connection: pid=30935 Apr 3 15:19:06 fourier dovecot: auth(default): new auth connection: pid=30936 Apr 3 15:19:21 fourier dovecot: auth(default): new auth connection: pid=30974 Apr 3 15:19:28 fourier dovecot: auth(default): client in: AUTH^I1^IPLAIN^Iservice=IMAP^Isecured^Ilip=x.x.x.x^Irip=y.y.y.y^Iresp=<hidden> Apr 3 15:19:28 fourier dovecot: auth(default): ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com)) Apr 3 15:22:28 fourier dovecot: imap-login: Disconnected: Inactivity: method=PLAIN, rip=y.y.y.y, lip=x.x.x.x, TLS

On Fri, 2008-04-04 at 00:11 +0300, Timo Sirainen wrote:

...

No, I mean this appears to be a bug somewhere since a LDAP request is
sent, but it's never received by Dovecot. So either Dovecot does
something wrong, OpenLDAP library does something wrong or your network
blocks the reply for some reason. For example on my system:

auth(default): ldap(foo,127.0.0.1): bind search: base=... auth(default): ldap(foo,127.0.0.1): result: uid(user)=foo

If Dovecot receives a reply to the "bind search", it logs the "result"
line, which your logs show is missing.

On Apr 4, 2008, at 12:06 AM, Jack McKinney wrote:

...
I am not sure that I understand you, here. Are you saying that I am missing something from my configuration after the "filter=" line
like a pass_attrs listing fields to return? I do not have one, as there
are no fields that I need returned. The only thing that dovecot needs is the DN of the match itself.

According to http://wiki.dovecot.org/AuthDatabase/LDAP ,

"The pass_filter is used to find the LDAP entry, and the DN is taken from the reply."

Should I add a dummy pass_attrs entry? What field is safe to grab? E.g., I do not want to overwrite "user"...

On Thu, 2008-04-03 at 23:59 +0300, Timo Sirainen wrote:

...
On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...
ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))

Here should be a line saying "result: <returned fields>". Since there isn't, Dovecot never appears to receive the reply. You could verify
this by adding to src/auth/db-ldap.c ldap_input() around line 372:
  msgid = ldap_msgid(res);
// added line: i_info("LDAP: Received reply %d", msgid);

msgid might be the same as this tag:

...
Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT
tag=101

But I'm not sure. If you anyway receive a reply after the "bind
search", there's something wrong in Dovecot's error handling.
-- Jack McKinney GPG 1024D/99C6A174 jackmc@lorentz.com YM:lfaatsnat2006 AIM:jackmclorentz "There is no parameter that makes it impossible for you to perform
still more excellently." -Mario Cuomo, on the lack of a clock in baseball

Jack McKinney

12:50 a.m.

Hmmm... what versions of OpenLDAP and Dovecot are you using? I note

that you got a result of "uid(user)=foo", from which I guess that you had pass_attrs set to user=uid or some such. I tried adding a pass_attrs of user=mail, in case the problem is that without requested fields, the code in dovecot doesn't return anything. It didn't work; it still hangs and times out after 3 minutes.

On Fri, 2008-04-04 at 00:11 +0300, Timo Sirainen wrote:

...

No, I mean this appears to be a bug somewhere since a LDAP request is
sent, but it's never received by Dovecot. So either Dovecot does
something wrong, OpenLDAP library does something wrong or your network
blocks the reply for some reason. For example on my system:

auth(default): ldap(foo,127.0.0.1): bind search: base=... auth(default): ldap(foo,127.0.0.1): result: uid(user)=foo

If Dovecot receives a reply to the "bind search", it logs the "result"
line, which your logs show is missing.

On Apr 4, 2008, at 12:06 AM, Jack McKinney wrote:

...
I am not sure that I understand you, here. Are you saying that I am missing something from my configuration after the "filter=" line
like a pass_attrs listing fields to return? I do not have one, as there
are no fields that I need returned. The only thing that dovecot needs is the DN of the match itself.

According to http://wiki.dovecot.org/AuthDatabase/LDAP ,

"The pass_filter is used to find the LDAP entry, and the DN is taken from the reply."

Should I add a dummy pass_attrs entry? What field is safe to grab? E.g., I do not want to overwrite "user"...

On Thu, 2008-04-03 at 23:59 +0300, Timo Sirainen wrote:

...
On Thu, 2008-04-03 at 09:46 -0500, Jack McKinney wrote:

...
ldap(jackmc@lorentz.com,y.y.y.y): bind search: base=ou=users, dc=lorentz,dc=com filter=(&(objectClass=inetOrgPerson)(mail=jackmc@lorentz.com))

Here should be a line saying "result: <returned fields>". Since there isn't, Dovecot never appears to receive the reply. You could verify
this by adding to src/auth/db-ldap.c ldap_input() around line 372:
  msgid = ldap_msgid(res);
// added line: i_info("LDAP: Received reply %d", msgid);

msgid might be the same as this tag:

...
Apr 3 08:13:30 fourier slapd[14039]: conn=7 op=3 SEARCH RESULT
tag=101

But I'm not sure. If you anyway receive a reply after the "bind
search", there's something wrong in Dovecot's error handling.
-- Jack McKinney GPG 1024D/99C6A174 jackmc@lorentz.com YM:lfaatsnat2006 AIM:jackmclorentz "There is no parameter that makes it impossible for you to perform
still more excellently." -Mario Cuomo, on the lack of a clock in baseball

Timo Sirainen

9:54 a.m.

On Apr 4, 2008, at 12:50 AM, Jack McKinney wrote:

...

Hmmm... what versions of OpenLDAP and Dovecot are you using?

A lot of people have them working with different LDAP versions. I've
Debian unstable's OpenLDAP 2.1.30.dfsg-13.5.

...

I note that you got a result of "uid(user)=foo", from which I guess that you had pass_attrs set to user=uid or some such. I tried adding a pass_attrs of user=mail, in case the problem is that without requested fields, the code in dovecot doesn't return anything. It didn't work; it still hangs and times out after 3 minutes.

Check with wireshark if it shows that LDAP server really sends the
reply. Then you could find out if it's a problem on the OpenLDAP
client side or server/network side.

Jack McKinney

4:48 p.m.

Is wireshark something like tcpdump?
My LDAP server and my Dovecot server are on the same machine, and the

LDAP server claims to send the response. Since the same query from a CLI tool (ldapsearch) creates the same LDAP log entries, I suspect that OpenLDAP is indeed sending, but Dovecot is not receiving...

On Fri, 2008-04-04 at 09:54 +0300, Timo Sirainen wrote:

...

On Apr 4, 2008, at 12:50 AM, Jack McKinney wrote:

...
Hmmm... what versions of OpenLDAP and Dovecot are you using?

A lot of people have them working with different LDAP versions. I've
Debian unstable's OpenLDAP 2.1.30.dfsg-13.5.

...
I note that you got a result of "uid(user)=foo", from which I guess that you had pass_attrs set to user=uid or some such. I tried adding a pass_attrs of user=mail, in case the problem is that without requested fields, the code in dovecot doesn't return anything. It didn't work; it still hangs and times out after 3 minutes.

Check with wireshark if it shows that LDAP server really sends the
reply. Then you could find out if it's a problem on the OpenLDAP
client side or server/network side.

Timo Sirainen

5:20 p.m.

On Fri, 2008-04-04 at 08:48 -0500, Jack McKinney wrote:

...

Is wireshark something like tcpdump?

Yes, except it parses the replies so it can show the LDAP request/reply values.

...

My LDAP server and my Dovecot server are on the same machine, and the LDAP server claims to send the response. Since the same query from a CLI tool (ldapsearch) creates the same LDAP log entries, I suspect that OpenLDAP is indeed sending, but Dovecot is not receiving...

But as you noticed with those i_info() lines, Dovecot didn't receive the reply from OpenLDAP. So there's something wrong in the middle.

Also a lot of people have LDAP working fine, so I doubt the problem is with Dovecot's code.

Jack McKinney

5:47 p.m.

Me, too.  I am sure that it is my configuration, but I cannot see

what...

On Fri, 2008-04-04 at 17:20 +0300, Timo Sirainen wrote:

Jack McKinney GPG 1024D/99C6A174 jackmc@lorentz.com YM:lfaatsnat2006 AIM:jackmclorentz "There is no parameter that makes it impossible for you to perform still more excellently." -Mario Cuomo, on the lack of a clock in baseball

6068

Age (days ago)

6069

Last active (days ago)

List overview

11 comments

2 participants

participants (2)

Jack McKinney
Timo Sirainen