[Date Prev][Date Next] [Chronological] [Thread] [Top]

slapd-passwd backend problems

To: openldap-technical@openldap.org
Subject: slapd-passwd backend problems
From: Lawrence Stewart <lstewart@room52.net>
Date: Mon, 16 Jun 2008 13:35:53 +1000
User-agent: Thunderbird 2.0.0.14 (X11/20080530)

Hi all,

I'm attempting to set up a very simple passwd database backed slapd instance and can't seem to make it work reliably. A number of hours on google and experimenting with options has not been fruitful so far.

I'm running openldap 2.4.10 on FreeBSD 7.0


My slapd.conf looks like this:

##############################################
include         /usr/local/etc/openldap/schema/core.schema
loglevel        conns filter stats
pidfile         /var/run/openldap/slapd.pid
argsfile        /var/run/openldap/slapd.args
modulepath      /usr/local/libexec/openldap
moduleload      back_passwd
moduleload      back_monitor

access to *
  by anonymous read

database        passwd
readonly        yes
suffix          "dc=example,dc=com"
rootdn          "cn=root,dc=example,dc=com"
rootpw          <passwod>

database monitor
##############################################

I am able to successfully start slapd and I can successfully query for a user by running the following command on the server itself:

ldapsearch -x -H ldap://127.0.0.1 -b 'dc=example,dc=com' 'uid=test'

which correctly returns the following details about the test user already in the system's passwd database:


##############################################
# extended LDIF
#
# LDAPv3
# base <dc=example,dc=com> with scope subtree
# filter: uid=test
# requesting: ALL
#

# test, example.com
dn: uid=test,dc=example,dc=com
objectClass: person
objectClass: uidObject
uid: test
cn: test
cn: Testy McTest
sn: test
sn: McTest
description: Testy McTest

# search result
search: 2
result: 0 Success

# numResponses: 2
# numEntries: 1
##############################################

However, attempting an identical, additional query after the first one results in an empty search being returned:


##############################################
# extended LDIF
#
# LDAPv3
# base <dc=example,dc=com> with scope subtree
# filter: uid=test
# requesting: ALL
#

# search result
search: 2
result: 0 Success

# numResponses: 1
##############################################

I have experimented with many different options in slapd.conf and have not found anything that is able to mitigate this behaviour. The only way I have found to make an additional query work successfully is to restart slapd. After a restart, I can successfully make a single query again and then it stops returning a query result.

The debugging output from slapd when a query is successful looks like this:

############################################## Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: waked Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: listen=7, new connection on 8 Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: added 8r (active) listener=0x0 Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 fd=8 ACCEPT from IP=127.0.0.1:59836 (IP=0.0.0.0:389) Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: waked Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:19:29 newtcp8 slapd[11410]: 8r Jun 16 13:19:29 newtcp8 slapd[11410]: Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: waked Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 op=0 BIND dn="" method=128 Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 op=0 RESULT tag=97 err=0 text= Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:19:29 newtcp8 slapd[11410]: 8r Jun 16 13:19:29 newtcp8 slapd[11410]: Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: waked Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: begin get_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: end get_filter 0 Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 op=1 SRCH base="dc=example,dc=com" scope=2 deref=0 filter="(uid=test)" Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:19:29 newtcp8 slapd[11410]: => test_filter Jun 16 13:19:29 newtcp8 slapd[11410]: EQUALITY Jun 16 13:19:29 newtcp8 slapd[11410]: <= test_filter 6 Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text= Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:19:29 newtcp8 slapd[11410]: 8r Jun 16 13:19:29 newtcp8 slapd[11410]: Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: connection_read(8): input error=-2 id=0, closing. Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 op=2 UNBIND Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: removing 8 Jun 16 13:19:29 newtcp8 slapd[11410]: conn=0 fd=8 closed Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: waked Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:19:29 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL ##############################################

and for an unsuccessful query looks like this:

############################################## Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 busy Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: listen=7, new connection on 8 Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: added 8r (active) listener=0x0 Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 fd=8 ACCEPT from IP=127.0.0.1:64362 (IP=0.0.0.0:389) Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: waked Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:22:21 newtcp8 slapd[11410]: 8r Jun 16 13:22:21 newtcp8 slapd[11410]: Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 op=0 BIND dn="" method=128 Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 op=0 RESULT tag=97 err=0 text= Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: waked Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:22:21 newtcp8 slapd[11410]: 8r Jun 16 13:22:21 newtcp8 slapd[11410]: Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: begin get_filter Jun 16 13:22:21 newtcp8 slapd[11410]: EQUALITY Jun 16 13:22:21 newtcp8 slapd[11410]: end get_filter 0 Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 op=1 SRCH base="dc=example,dc=com" scope=2 deref=0 filter="(uid=test)" Jun 16 13:22:21 newtcp8 slapd[11410]: => test_filter Jun 16 13:22:21 newtcp8 slapd[11410]: EQUALITY Jun 16 13:22:21 newtcp8 slapd[11410]: <= test_filter 5 Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 op=1 SEARCH RESULT tag=101 err=0 nentries=0 text= Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: waked Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on: Jun 16 13:22:21 newtcp8 slapd[11410]: 8r Jun 16 13:22:21 newtcp8 slapd[11410]: Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: read activity on 8 Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: connection_read(8): input error=-2 id=1, closing. Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 op=2 UNBIND Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: removing 8 Jun 16 13:22:21 newtcp8 slapd[11410]: conn=1 fd=8 closed Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: activity on 1 descriptor Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: waked Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=6 active_threads=0 tvp=NULL Jun 16 13:22:21 newtcp8 slapd[11410]: daemon: select: listen=7 active_threads=0 tvp=NULL ##############################################

I have analysed both sets of debug output and there are no material differences except that the successful query applies a number of equality test operations (indicating it is successfully walking through the entries in the passwd file) where as the failed query only applies 1 equality test. It's like the subsequent queries are not causing a full re-walk of the passwd database to find a match, but that's pure speculation at this point.

Any insights into why the passwd backend might be behaving like this would be greatly appreciated.

Please let me know if additional information or more detailed debugging output would help to diagnose the issue.

Thanks in advance.

Cheers,
Lawrence

Prev by Date: LDAP ACL/ ADRESSBOOK Problems and more
Next by Date: Thunderbird & OpenLDAP
Index(es):
- Chronological
- Thread