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