after restart slapd server I cannot search single record in ldap servers - openldap-technical

27 Jul 2011


      Hello,
I set up an slapd with slapd-meta backend. I have two Active Directory
servers which don't share any portion of naming context. I would like
to get one virtual domain. I configure it and it works fine until I
restart slapd server. When I restart slapd server then I am unable to
search in my ldap servers single record.
When I search one single record (samAccountName=testdom1) then I have
got 0 result.
root@slapd:~# ldapsearch -b 'dc=dom,dc=com' -h 172.30.14.190 -p 389 -D
'cn=Manager,dc=dom,dc=com' -w secret '(samAccountName=testdom1)'
# extended LDIF
#
# LDAPv3
# base <dc=dom,dc=com> with scope subtree
# filter: (samAccountName=testdom1)
# requesting: ALL
#
# search result
search: 2
result: 0 Success
# numResponses: 1
root@slapd:~#
In the log (full debug) I have:
Jul 27 16:12:17 dom slapd[12096]: daemon: read active on 9
Jul 27 16:12:17 dom slapd[12096]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Jul 27 16:12:17 dom slapd[12096]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Jul 27 16:12:17 dom slapd[12096]: connection_get(9)
Jul 27 16:12:17 dom slapd[12096]: connection_get(9): got connid=1000
Jul 27 16:12:17 dom slapd[12096]: connection_read(9): checking for
input on id=1000
Jul 27 16:12:17 dom slapd[12096]: op tag 0x42, time 1311775937
Jul 27 16:12:17 dom slapd[12096]: ber_get_next on fd 9 failed errno=0 (Success)
Jul 27 16:12:17 dom slapd[12096]: connection_read(9): input error=-2
id=1000, closing.
Jul 27 16:12:17 dom slapd[12096]: connection_closing: readying
conn=1000 sd=9 for close
Jul 27 16:12:17 dom slapd[12096]: connection_close: deferring conn=1000 sd=9
Jul 27 16:12:17 dom slapd[12096]: conn=1000 op=2 do_unbind
Jul 27 16:12:17 dom slapd[12096]: conn=1000 op=2 UNBIND
Jul 27 16:12:17 dom slapd[12096]: connection_resched: attempting
closing conn=1000 sd=9
Jul 27 16:12:17 dom slapd[12096]: connection_close: deferring conn=1000 sd=9
Jul 27 16:12:17 dom slapd[12096]: daemon: activity on 1 descriptor
Jul 27 16:12:17 dom slapd[12096]: daemon: activity on:
Jul 27 16:12:17 dom slapd[12096]:
Jul 27 16:12:17 dom slapd[12096]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Jul 27 16:12:17 dom slapd[12096]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Jul 27 16:12:17 dom slapd[12096]: conn=1000 op=1 SEARCH RESULT tag=101
err=0 nentries=0 text=
Jul 27 16:12:17 dom slapd[12096]: connection_resched: attempting
closing conn=1000 sd=9
Jul 27 16:12:17 dom slapd[12096]: connection_close: conn=1000 sd=9
Jul 27 16:12:17 dom slapd[12096]: =>meta_back_conn_destroy: fetching
conn=1000 DN="cn=manager,dc=dom,dc=com"
Jul 27 16:12:17 dom slapd[12096]: daemon: removing 9
Jul 27 16:12:17 dom slapd[12096]: conn=1000 fd=9 closed
Then when I search full list of record (samAccountName=*) I have got
full list of records from two ldap servers.
root@slapd:~# ldapsearch -b 'dc=dom,dc=com' -h 172.30.14.190 -p 389 -D
'cn=Manager,dc=dom,dc=com' -w secret '(samAccountName=*)'
# search result
search: 2
result: 0 Success
# numResponses: 39
# numEntries: 38
root@slapd:~#
And this is the trick. From now... When I again search one single
record I got correct result - until I restart slapd server again. I
don't know what can be wrong. Any ideas?
root@slapd:~# ldapsearch -b 'dc=dom,dc=com' -h 172.30.14.190 -p 389 -D
'cn=Manager,dc=dom,dc=com' -w secret '(samAccountName=testdom1)'
# extended LDIF
#
# LDAPv3
# base <dc=dom,dc=com> with scope subtree
# filter: (samAccountName=testdom1)
# requesting: ALL
#
# testdom1, dom.com
dn: cn=testdom1,dc=dom,dc=com
objectClass: top
objectClass: person
objectClass: organizationalPerson
objectClass: USER
cn: testdom1
givenName: testdom1
distinguishedName: cn=testdom1,dc=dom,dc=com
INSTANCETYPE: 4
WHENCREATED: 20110726100434.0Z
WHENCHANGED: 20110726160313.0Z
DISPLAYNAME: testdom1
USNCREATED: 24630
USNCHANGED: 24756
name: testdom1
OBJECTGUID:: +ERwSjOp5Uex1n86v5CurA==
USERACCOUNTCONTROL: 66048
BADPWDCOUNT: 0
CODEPAGE: 0
COUNTRYCODE: 0
BADPASSWORDTIME: 129561692315625000
LASTLOGOFF: 0
LASTLOGON: 129561692402968750
PWDLASTSET: 129561697935781250
PRIMARYGROUPID: 513
OBJECTSID:: AQUAAAAAAAUVAAAAMkafw9OC5FYbZ2/5UwQAAA==
ACCOUNTEXPIRES: 9223372036854775807
LOGONCOUNT: 0
SAMACCOUNTNAME: testdom1
SAMACCOUNTTYPE: 805306368
USERPRINCIPALNAME: testdom1@dom1.com
OBJECTCATEGORY: CN=Person,CN=Schema,CN=Configuration,DC=dom1,DC=com
# search result
search: 2
result: 0 Success
# numResponses: 2
# numEntries: 1
root@slapd:~#
The log:
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "BADPWDCOUNT" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (CODEPAGE)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "CODEPAGE" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (COUNTRYCODE)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "COUNTRYCODE" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (BADPASSWORDTIME)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "BADPASSWORDTIME" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (LASTLOGOFF)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "LASTLOGOFF" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (LASTLOGON)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "LASTLOGON" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (PWDLASTSET)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "PWDLASTSET" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (PRIMARYGROUPID)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "PRIMARYGROUPID" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (OBJECTSID)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "OBJECTSID" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (ACCOUNTEXPIRES)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "ACCOUNTEXPIRES" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (LOGONCOUNT)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "LOGONCOUNT" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (SAMACCOUNTNAME)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "SAMACCOUNTNAME" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (SAMACCOUNTTYPE)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "SAMACCOUNTTYPE" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (USERPRINCIPALNAME)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "USERPRINCIPALNAME" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: result not in
cache (OBJECTCATEGORY)
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access to
"cn=testdom1,dc=dom,dc=com" "OBJECTCATEGORY" requested
Jul 27 16:19:22 dom slapd[12096]: <= root access granted
Jul 27 16:19:22 dom slapd[12096]: => access_allowed: read access
granted by manage(=mwrscxd)
Jul 27 16:19:22 dom slapd[12096]: conn=1003 op=1 ENTRY
dn="cn=testdom1,dc=dom,dc=com"
Jul 27 16:19:22 dom slapd[12096]: <= send_search_entry: conn 1003 exit.
Jul 27 16:19:22 dom slapd[12096]: send_ldap_result: conn=1003 op=1 p=3
Jul 27 16:19:22 dom slapd[12096]: send_ldap_result: err=0 matched="" text=""
Jul 27 16:19:22 dom slapd[12096]: send_ldap_response: msgid=2 tag=101 err=0
Jul 27 16:19:22 dom slapd[12096]: conn=1003 op=1 SEARCH RESULT tag=101
err=0 nentries=1 text=
Jul 27 16:19:22 dom slapd[12096]: daemon: activity on 1 descriptor
Jul 27 16:19:22 dom slapd[12096]: daemon: activity on:
Jul 27 16:19:22 dom slapd[12096]:  9r
Jul 27 16:19:22 dom slapd[12096]:
Jul 27 16:19:22 dom slapd[12096]: daemon: read active on 9
Jul 27 16:19:22 dom slapd[12096]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Jul 27 16:19:22 dom slapd[12096]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Jul 27 16:19:22 dom slapd[12096]: connection_get(9)
Jul 27 16:19:22 dom slapd[12096]: connection_get(9): got connid=1003
Jul 27 16:19:22 dom slapd[12096]: connection_read(9): checking for
input on id=1003
Jul 27 16:19:22 dom slapd[12096]: op tag 0x42, time 1311776362
Jul 27 16:19:22 dom slapd[12096]: ber_get_next on fd 9 failed errno=0 (Success)
Jul 27 16:19:22 dom slapd[12096]: connection_read(9): input error=-2
id=1003, closing.
Jul 27 16:19:22 dom slapd[12096]: connection_closing: readying
conn=1003 sd=9 for close
Jul 27 16:19:22 dom slapd[12096]: connection_close: deferring conn=1003 sd=9
Jul 27 16:19:22 dom slapd[12096]: conn=1003 op=2 do_unbind
Jul 27 16:19:22 dom slapd[12096]: conn=1003 op=2 UNBIND
Jul 27 16:19:22 dom slapd[12096]: connection_resched: attempting
closing conn=1003 sd=9
Jul 27 16:19:22 dom slapd[12096]: connection_close: deferring conn=1003 sd=9
Jul 27 16:19:22 dom slapd[12096]: daemon: activity on 1 descriptor
Jul 27 16:19:22 dom slapd[12096]: daemon: activity on:
Jul 27 16:19:22 dom slapd[12096]:
Jul 27 16:19:22 dom slapd[12096]: daemon: epoll: listen=7
active_threads=0 tvp=NULL
Jul 27 16:19:22 dom slapd[12096]: daemon: epoll: listen=8
active_threads=0 tvp=NULL
Jul 27 16:19:22 dom slapd[12096]: connection_resched: attempting
closing conn=1003 sd=9
Jul 27 16:19:22 dom slapd[12096]: connection_close: conn=1003 sd=9
Jul 27 16:19:22 dom slapd[12096]: =>meta_back_conn_destroy: fetching
conn=1003 DN="cn=manager,dc=dom,dc=com"
Jul 27 16:19:22 dom slapd[12096]: daemon: removing 9
Jul 27 16:19:22 dom slapd[12096]: conn=1003 fd=9 closed
My OpenLDAP version:
root@slapd:~# slapd -V
@(#) $OpenLDAP: slapd 2.4.23 (Jul 26 2011 14:53:23) $
        root@slapd:/root/openldap-2.4.23/servers/slapd
My slapd.conf:
root@slapd:~# cat /usr/local/etc/openldap/slapd.conf
#
# See slapd.conf(5) for details on configuration options.
# This file should NOT be world readable.
#
include         /usr/local/etc/openldap/schema/core.schema
# Define global ACLs to disable default read access.
# Do not enable referrals until AFTER you have a working directory
# service AND an understanding of referrals.
#referral       ldap://root.openldap.org
pidfile         /usr/local/var/run/slapd.pid
argsfile        /usr/local/var/run/slapd.args
# Load dynamic backend modules:
# modulepath    /usr/local/libexec/openldap
# moduleload    back_bdb.la
# moduleload    back_hdb.la
# moduleload    back_ldap.la
loglevel 0xFFFF
access to * by * read
#######################################################################
# database definitions
#######################################################################
database        meta
suffix          "dc=dom,dc=com"
rootdn          "cn=Manager,dc=dom,dc=com"
rootpw          secret
chase-referrals no
#nretries       forever
nretries        3
# 1 sec timeout for binds
bind-timeout    1000000
#norefs         true
dncache-ttl     DISABLED
conn-ttl        90
idle-timeout    1m30s
onerr           CONTINUE
# ldap1
uri             "ldap://dc1.dom1.com:389/dc=dom,dc=com"
suffixmassage   "dc=dom,dc=com" "cn=Users,dc=dom1,dc=com"
idassert-bind   bindmethod=simple
                binddn="cn=LDAPconnector,cn=Users,dc=dom1,dc=com"
                credentials="pass"
                mode=none
                flags=non-prescriptive
# ldap2
uri             "ldap://dc2.dom2.com:389/dc=dom,dc=com"
suffixmassage   "dc=dom,dc=com" "cn=Users,dc=dom2,dc=com"
idassert-bind   bindmethod=simple
                binddn="cn=LDAPconnector2,cn=Users,dc=dom2,dc=com"
                credentials="pass"
                mode=none
                flags=non-prescriptive
root@slapd:~#
King regards,
Marcin