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

[Benjamin Dauvergne]

Content preview: 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. [...]

Content analysis details: (-1.9 points, 5.0 required)

pts rule name description
---- ---------------------- --------------------------------------------------
-0.0 SPF_PASS SPF: sender matches SPF record
-1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
[score: 0.0000]

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

[Benjamin Dauvergne]

Here is the full LDIF file which also contains the cn=config
configuration of the newly created DB (sill ldapvi LDIF syntax).

Post by Benjamin Dauvergne
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,
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
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...
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]: => 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.
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

[Benjamin Dauvergne]

Content preview: Le 06/02, Benjamin Dauvergne a écrit : > Here is the full
LDIF file which also contains the cn=config > configuration of the newly created
DB (sill ldapvi LDIF syntax). Ok I found it, it's related to the slapo-unique
overlay, I'm gonna open an ITS for it. Problem seems related to a missing
basedn in the LDAP URI used for the uniqueURI setting. [...]

Content analysis details: (-1.9 points, 5.0 required)

pts rule name description
---- ---------------------- --------------------------------------------------
-0.0 SPF_PASS SPF: sender matches SPF record
-1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
[score: 0.0000]
X-Mailman-Approved-At: Tue, 02 Jun 2015 18:41:55 +0000
X-BeenThere: openldap-***@openldap.org
X-Mailman-Version: 2.1.15
Precedence: list
List-Id: OpenLDAP development discussion list <openldap-devel.openldap.org>
List-Unsubscribe: <http://www.openldap.org/lists/mm/options/openldap-devel>,
<mailto:openldap-devel-***@openldap.org?subject=unsubscribe>
List-Archive: <http://www.openldap.org/lists/openldap-devel/>
List-Post: <mailto:openldap-***@openldap.org>
List-Help: <mailto:openldap-devel-***@openldap.org?subject=help>
List-Subscribe: <http://www.openldap.org/lists/mm/listinfo/openldap-devel>,
<mailto:openldap-devel-***@openldap.org?subject=subscribe>
Errors-To: openldap-devel-***@openldap.org
Sender: "openldap-devel" <openldap-devel-***@openldap.org>
X-Spam-Score: -1.9 (-)
X-Spam-Report: Spam detection software, running on the system "gauss.openldap.net", has
identified this incoming email as possible spam. The original message
has been attached to this so you can view it (if it isn't spam) or label
similar future email. If you have any questions, see
the administrator of that system for details.

Content preview: Le 06/02, Benjamin Dauvergne a écrit : > Here is the full
LDIF file which also contains the cn=config > configuration of the newly created
DB (sill ldapvi LDIF syntax). Ok I found it, it's related to the slapo-unique
overlay, I'm gonna open an ITS for it. Problem seems related to a missing
basedn in the LDAP URI used for the uniqueURI setting. [...]

Content analysis details: (-1.9 points, 5.0 required)

pts rule name description
---- ---------------------- --------------------------------------------------
-0.0 SPF_PASS SPF: sender matches SPF record
-1.9 BAYES_00 BODY: Bayes spam probability is 0 to 1%
[score: 0.0000]

Post by Benjamin Dauvergne
Here is the full LDIF file which also contains the cn=config
configuration of the newly created DB (sill ldapvi LDIF syntax).

Ok I found it, it's related to the slapo-unique overlay, I'm gonna open
an ITS for it. Problem seems related to a missing basedn in the LDAP URI
used for the uniqueURI setting.