[imp] Problems using ldap for authentication and preferences - competing ldap operations?

Wed Jan 29 10:56:49 PST 2003

I'm having problems getting IMP to work when using ldap for both
preferences and authentication.  From my logs it appears to me that
there are some competing operations going on between authentications and
retrieving the preferences.  The horde log shows that at one point the
bind to the server with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu fails, yet it
successfully binds with that DN at other points.

Is anyone out there using ldap both for preferences and authentication
successfully or do I have something screwed up somewhere?  Any help
would be greatly appreciated.  Some output from my logs is pasted below.

Rob

sldap.log while using ldap for preferences

Jan 29 10:07:36 stumail slapd[12810]: conn=14 fd=15 ACCEPT from
IP=127.0.0.1:34430 (IP=0.0.0.0:389)

Jan 29 10:07:36 stumail slapd[12826]: conn=14 op=0 BIND dn="" method=128

Jan 29 10:07:36 stumail slapd[12826]: conn=14 op=0 RESULT tag=97 err=0
text=

Jan 29 10:07:36 stumail slapd[12825]: conn=14 op=1 SRCH
base="dc=stumail,dc=bergen,dc=edu" scope=2 filter="(uid=lsmith)"

Jan 29 10:07:36 stumail slapd[12825]: conn=14 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=

Jan 29 10:07:36 stumail slapd[12827]: conn=14 op=2 BIND
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu" method=128

Jan 29 10:07:36 stumail slapd[12827]: conn=14 op=2 AUTHZ
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu"
mech=simple ssf=0

Jan 29 10:07:36 stumail slapd[12827]: conn=14 op=2 RESULT tag=97 err=0
text=

Jan 29 10:07:36 stumail slapd[12826]: conn=14 op=3 AUTHZ anonymous
mech=implicit ssf=0

Jan 29 10:07:36 stumail slapd[12826]: conn=14 op=3 BIND dn="" method=128

Jan 29 10:07:36 stumail slapd[12826]: conn=14 op=3 RESULT tag=97 err=0
text=

Jan 29 10:07:36 stumail slapd[12810]: deferring operation

Jan 29 10:07:36 stumail slapd[12826]: conn=14 fd=15 closed

sldap.log while using MySQL backend for preferences

Jan 29 10:11:51 stumail slapd[12810]: conn=17 fd=15 ACCEPT from
IP=127.0.0.1:34436 (IP=0.0.0.0:389)

Jan 29 10:11:51 stumail slapd[12826]: conn=17 op=0 BIND dn="" method=128

Jan 29 10:11:51 stumail slapd[12826]: conn=17 op=0 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12825]: conn=17 op=1 SRCH
base="dc=stumail,dc=bergen,dc=edu" scope=2 filter="(uid=lsmith)"

Jan 29 10:11:51 stumail slapd[12825]: conn=17 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=

Jan 29 10:11:51 stumail slapd[12827]: conn=17 op=2 BIND
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu" method=128

Jan 29 10:11:51 stumail slapd[12827]: conn=17 op=2 AUTHZ
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu"
mech=simple ssf=0

Jan 29 10:11:51 stumail slapd[12827]: conn=17 op=2 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12826]: conn=17 op=3 AUTHZ anonymous
mech=implicit ssf=0

Jan 29 10:11:51 stumail slapd[12826]: conn=17 op=3 BIND dn="" method=128

Jan 29 10:11:51 stumail slapd[12826]: conn=17 op=3 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12825]: conn=17 op=4 UNBIND

Jan 29 10:11:51 stumail slapd[12825]: conn=17 fd=15 closed

Jan 29 10:11:51 stumail slapd[12810]: conn=18 fd=15 ACCEPT from
IP=127.0.0.1:34438 (IP=0.0.0.0:389)

Jan 29 10:11:51 stumail slapd[12827]: conn=18 op=0 BIND dn="" method=128

Jan 29 10:11:51 stumail slapd[12827]: conn=18 op=0 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12826]: conn=18 op=1 SRCH
base="dc=stumail,dc=bergen,dc=edu" scope=2 filter="(uid=lsmith)"

Jan 29 10:11:51 stumail slapd[12826]: conn=18 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=

Jan 29 10:11:51 stumail slapd[12825]: conn=18 op=2 BIND
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu" method=128

Jan 29 10:11:51 stumail slapd[12825]: conn=18 op=2 AUTHZ
dn="cn=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu"
mech=simple ssf=0

Jan 29 10:11:51 stumail slapd[12825]: conn=18 op=2 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12827]: conn=18 op=3 AUTHZ anonymous
mech=implicit ssf=0

Jan 29 10:11:51 stumail slapd[12827]: conn=18 op=3 BIND dn="" method=128

Jan 29 10:11:51 stumail slapd[12827]: conn=18 op=3 RESULT tag=97 err=0
text=

Jan 29 10:11:51 stumail slapd[12825]: conn=18 op=4 UNBIND

Jan 29 10:11:51 stumail slapd[12825]: conn=18 fd=15 closed

horde.log with message level = LOG_DEBUG

Jan 29 10:32:27 HORDE [info] [imp] Bind to server :389 with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu failed: [81]
Can't contact LDAP server [on line 176 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:32:27 HORDE [info] [imp] Failed to connect to LDAP preferences
server. [on line 333 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:32:27 HORDE [info] [imp] No preferences were retrieved. [on
line 370 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:32:27 HORDE [notice] [imp] Login success for
lsmith at stumail.bergen.edu [10.2.34.1] to {localhost:143} [on line 64 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/imp/redirect.php"]

Jan 29 10:32:27 HORDE [info] [imp] Unable to modify preferences: [81]
Can't contact LDAP server [on line 447 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:10 HORDE [info] [horde] Bind to server :389 with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu failed: [81]
Can't contact LDAP server [on line 178 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

At this point I the user gets a screen that says:

Warning: LDAP: Unable to perform the search: Can't contact LDAP server
in /usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php on line
327

Warning: LDAP: modify operation could not be completed. in
/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php on line 438

Warning: Cannot add header information - headers already sent by (output
started at
/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php:327) in
/usr/local/etc/apache_1.3.26/htdocs/horde/imp/redirect.php on line 75

Then when the mail icon is clicked the user is logged in and taken
successfully to their inbox.

Jan 29 10:39:10 HORDE [info] [horde] Failed to connect to LDAP
preferences server. [on line 335 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:10 HORDE [info] [horde] No preferences were retrieved. [on
line 372 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:11 HORDE [notice] [imp] Logout for
lsmith at stumail.bergen.edu [10.2.34.1] from {localhost:143} [on line 34
of "/usr/local/etc/apache_1.3.26/htdocs/horde/imp/login.php"]

Jan 29 10:39:13 HORDE [info] [imp] Bind to server :389 with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu failed: [81]
Can't contact LDAP server [on line 178 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:13 HORDE [info] [imp] Unable to modify preferences: [81]
Can't contact LDAP server [on line 449 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:37 HORDE [info] [imp] Bind to server :389 with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu failed: [81]
Can't contact LDAP server [on line 178 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:37 HORDE [info] [imp] Failed to connect to LDAP preferences
server. [on line 335 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:37 HORDE [info] [imp] No preferences were retrieved. [on
line 372 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:39:37 HORDE [notice] [imp] Login success for
lsmith at stumail.bergen.edu [10.2.34.1] to {localhost:143} [on line 64 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/imp/redirect.php"]

Jan 29 10:39:37 HORDE [info] [imp] Unable to modify preferences: [81]
Can't contact LDAP server [on line 449 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:56:27 HORDE [info] [imp] Bind to server :389 with DN
uid=lsmith at stumail.bergen.edu,dc=stumail,dc=bergen,dc=edu failed: [81]
Can't contact LDAP server [on line 176 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Jan 29 10:56:27 HORDE [info] [imp] Unable to modify preferences: [81]
Can't contact LDAP server [on line 447 of
"/usr/local/etc/apache_1.3.26/htdocs/horde/lib/Prefs/ldap.php"]

Robert K. Kubarych

(201) 612-5591