Infinite loop with "mdb_search: 124xxxx1 scope not okay" while adding an entry

[Benjamin Dauvergne <bdauvergne@entrouvert.com>]

Hi,

I'm using OpenLDAP debian package from wheezy-backports (version
2.4.31+really2.4.40+dfsg) which is a 2.4.40 but backported I think under
another version number to allow the jessie package to execute its migration
when upgrade time will come.

When trying to initialize a new DB by loading an LDIF file using ldapvi,
looking like that:

	add dc=coin2,dc=fr
	objectClass: organization
	objectClass: dcObject
	objectClass: eduOrg
	objectClass: supannOrg
	dc: coin2
	o: whatever
	supannEtablissement: {UAI}ccc

	add ou=people,dc=coin2,dc=fr
	objectClass: organizationalUnit
	ou: people

	add uid=admin,ou=people,dc=coin2,dc=fr
	objectClass: inetOrgPerson
	objectClass: eduPerson
	objectClass: supannPerson
	uid: admin
	cn: Administrateur annuaire
	displayName: Administrateur annuaire
	givenName: Administrateur
	sn: annuaire
	supannListeRouge: TRUE
	userPassword: xxxx
	supannEtablissement: {UAI}COIN

It blocks on adding the ou=people. After setting loglever to 255 I got my
syslog filled with such messages, soon filling the virtual machine virtual
disk:

Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 1 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 2 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 3 scope not okay
etc...

The log of the query finishing like that is:

Jun  2 02:34:26 ldap1-psl slapd[12159]: connection_get(15)
Jun  2 02:34:26 ldap1-psl slapd[12159]: connection_get(15): got connid=1001
Jun  2 02:34:26 ldap1-psl slapd[12159]: connection_read(15): checking for input on id=1001
Jun  2 02:34:26 ldap1-psl slapd[12159]: op tag 0x68, time 1433205266
Jun  2 02:34:26 ldap1-psl slapd[12159]: conn=1001 op=9 do_add
Jun  2 02:34:26 ldap1-psl slapd[12159]: conn=1001 op=9 do_add: dn (ou=people,dc=coin2,dc=fr)
Jun  2 02:34:26 ldap1-psl slapd[12159]: >>> dnPrettyNormal: <ou=people,dc=coin2,dc=fr>
Jun  2 02:34:26 ldap1-psl slapd[12159]: <<< dnPrettyNormal: <ou=people,dc=coin2,dc=fr>, <ou=people,dc=coin2,dc=fr>
Jun  2 02:34:26 ldap1-psl slapd[12159]: ==> unique_add <ou=people,dc=coin2,dc=fr>
Jun  2 02:34:26 ldap1-psl slapd[12159]: ==> unique_search (|(objectClass=organizationalUnit)(ou=people))
Jun  2 02:34:26 ldap1-psl slapd[12159]: str2filter "(|(objectClass=organizationalUnit)(ou=people))"
Jun  2 02:34:26 ldap1-psl slapd[12159]: begin get_filter
Jun  2 02:34:26 ldap1-psl slapd[12159]: OR
Jun  2 02:34:26 ldap1-psl slapd[12159]: begin get_filter_list
Jun  2 02:34:26 ldap1-psl slapd[12159]: begin get_filter
Jun  2 02:34:26 ldap1-psl slapd[12159]: EQUALITY
Jun  2 02:34:26 ldap1-psl slapd[12159]: end get_filter 0
Jun  2 02:34:26 ldap1-psl slapd[12159]: begin get_filter
Jun  2 02:34:26 ldap1-psl slapd[12159]: EQUALITY
Jun  2 02:34:26 ldap1-psl slapd[12159]: end get_filter 0
Jun  2 02:34:26 ldap1-psl slapd[12159]: end get_filter_list
Jun  2 02:34:26 ldap1-psl slapd[12159]: end get_filter 0
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_search
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_dn2entry("dc=coin2,dc=fr")
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_dn2id("dc=coin2,dc=fr")
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_dn2id: got id=0x1
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_entry_decode:
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_entry_decode
Jun  2 02:34:26 ldap1-psl slapd[12159]: => access_allowed: search access to "dc=coin2,dc=fr" "entry" requested
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= root access granted
Jun  2 02:34:26 ldap1-psl slapd[12159]: => access_allowed: search access granted by manage(=mwrscxd)
Jun  2 02:34:26 ldap1-psl slapd[12159]: search_candidates: base="dc=coin2,dc=fr" (0x00000001) scope=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_filter_candidates
Jun  2 02:34:26 ldap1-psl slapd[12159]: #011OR
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_list_candidates 0xa1
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_filter_candidates
Jun  2 02:34:26 ldap1-psl slapd[12159]: #011EQUALITY
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_equality_candidates (objectClass)
Jun  2 02:34:26 ldap1-psl slapd[12159]: => key_read
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_idl_fetch_key: [b49d1940]
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_index_read: failed (-30798)
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_equality_candidates: id=0, first=0, last=0
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_filter_candidates: id=0 first=0 last=0
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_filter_candidates
Jun  2 02:34:26 ldap1-psl slapd[12159]: #011OR
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_list_candidates 0xa1
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_filter_candidates
Jun  2 02:34:26 ldap1-psl slapd[12159]: #011EQUALITY
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_equality_candidates (objectClass)
Jun  2 02:34:26 ldap1-psl slapd[12159]: => key_read
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_idl_fetch_key: [9bee355f]
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_index_read: failed (-30798)
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_equality_candidates: id=0, first=0, last=0
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_filter_candidates: id=0 first=0 last=0
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_filter_candidates
Jun  2 02:34:26 ldap1-psl slapd[12159]: #011EQUALITY
Jun  2 02:34:26 ldap1-psl slapd[12159]: => mdb_equality_candidates (ou)
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_equality_candidates: (ou) not indexed
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_filter_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_list_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_filter_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_list_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: <= mdb_filter_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search_candidates: id=-1 first=1 last=-1
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 1 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 2 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 3 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 4 scope not okay
Jun  2 02:34:26 ldap1-psl slapd[12159]: mdb_search: 5 scope not okay
etc...

I don't know why it's doing a search on an add but seeing the message "(ou) not
indexed" I though that maybe adding an equality index on this attribute would
help, and effectively it did. Now the add ou=people passed, but it started
looping again when adding the uid=admin entry.

The infinite loop happen in server/slapd/back-mdb/search.c in mdb_search(). If
you have any idea I can continue investigating or add debug logs.

The debian package has the following patches applied over openldap 2.4.40:

add-tlscacert-option-to-ldap-conf
autogroup-makefile
contrib-modules-use-dpkg-buildflags
do-not-second-guess-sonames
evolution-ntlm
fix-build-top-mk
getaddrinfo-is-threadsafe
heimdal-fix
index-files-created-as-root
ITS6035-olcauthzregex-needs-restart.patch
ITS7975-fix-mdb-onelevel-search.patch
ITS8027-deref-reject-empty-attr-list.patch
ITS8046-fix-vrFilter_free-crash.patch
lastbind-makefile
ldap-conf-tls-cacertdir
ldapi-socket-place
libldap-symbol-versions
man-slapd
no-AM_INIT_AUTOMAKE
no-bdb-ABI-second-guessing
pw-sha2-makefile
sasl-default-path
slapi-errorlog-file
smbk5pwd-makefile
switch-to-lt_dlopenadvise-to-get-RTLD_GLOBAL-set.diff
wrong-database-location