Okay, here is the start of the search:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: conn=1001 op=1 do_search
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnPrettyNormal: <dc=cpp,dc=edu>
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnPrettyNormal:
<dc=cpp,dc=edu>, <dc=cpp,dc=edu>
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: SRCH "dc=cpp,dc=edu" 2 0 0 0 0
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: filter: (uid=henson)
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: attrs:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: ==> limits_get: conn=1001 op=1
self="[anonymous]" this="dc=cpp,dc=edu"
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <== limits_get: type=DN
match=ANONYMOUS
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_search
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu")
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu")
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: search_candidates:
base="dc=cpp,dc=edu" (0x00000001) scope=2
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_equality_candidates
(objectClass)
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => key_read
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [d913076f]
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_index_read 132354 candidates
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates:
id=-1, first=3, last=132356
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=-1
first=3 last=132356
It looks like is is looking for an objectClass match and then doing a
full scan of my entire directory? These lines are followed by thousands
and thousands of entries like:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnNormalize: <dc=cpp,dc=edu>
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnNormalize: <dc=cpp,dc=edu>
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnNormalize: <dc=cpp,dc=edu>
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnNormalize: <dc=cpp,dc=edu>
Then some "does not match filter" log lines start being interspersed,
again for thousands and thousands of lines:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1063 does not match
filter
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1064 does not match
filter
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1065 does not match
filter
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1066 does not match
filter
Until eventually it seems to be done looking at the object class attribute?
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_search
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: search_candidates:
base="dc=cpp,dc=edu" (0x00000001) scope=
2
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates
(objectClass)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [b49d1940]
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read: failed (-30798)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates:
id=0, first=0, last=0
It then looks for uid, for which I guess the index seems to be
functioning correctly, as only one record is returned:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (uid)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [6e61da89]
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read 1 candidates
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates:
id=1, first=3, last=3
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=1
first=3 last=3
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: >>> dnPrettyNormal: <dc=cpp,dc=edu>
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <<< dnPrettyNormal:
<dc=cpp,dc=edu>, <dc=cpp,dc=edu>
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_search
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Then it does a lookup on memberUid, presumably because I am using the
dynlist module to maintain memberOf:
dynlist-attrset cppEduPerson memberURL memberOf
and my entry has this attribute:
memberURL: ldap:///dc=cpp,dc=edu??sub?(memberUid=henson)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: search_candidates:
base="dc=cpp,dc=edu" (0x00000001) scope=2
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates
(memberUid)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [41e77321]
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read 31 candidates
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates:
id=31, first=1323, last=119410
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=31
first=1323 last=119410
that index also seems to be right, returning only 31 entries, and then
my entry seems to be returned to the client:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: conn=1001
op=1 p=3
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: err=0
matched="" text=""
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => send_search_entry: conn 1001
dn="uid=henson,ou=user,dc=c
pp,dc=edu"
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= send_search_entry: conn 1001
exit.
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: conn=1001
op=1 p=3
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: err=0
matched="" text=""
After that, however, it looks like all of the other entries in my
directory get traversed:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn:
"uid=he,ou=user,dc=cpp,dc=edu"
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)",
at: "(null)"
Oct 21 17:14:51 ldap-dev-03 slapd[4335]:
mdb_dn2entry("uid=he,ou=user,dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: =>
mdb_dn2id("uid=he,ou=user,dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0xb8c
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_entry_get: rc=0
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn:
"uid=hu,ou=user,dc=cpp,dc=edu"
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)",
at: "(null)"
Oct 21 17:14:51 ldap-dev-03 slapd[4335]:
mdb_dn2entry("uid=hu,ou=user,dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: =>
mdb_dn2id("uid=hu,ou=user,dc=cpp,dc=edu")
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0xe17
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_entry_get: rc=0
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn:
"uid=li,ou=user,dc=cpp,dc=edu"
[...]
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn:
"uid=ysabdelwahab,ou=user,dc=cpp,dc=
edu"
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)",
at: "(null)"
Oct 21 17:15:08 ldap-dev-03 slapd[4335]:
mdb_dn2entry("uid=ysabdelwahab,ou=user,dc=cpp,dc=edu")
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: =>
mdb_dn2id("uid=ysabdelwahab,ou=user,dc=cpp,dc=edu")
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1f4c8
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_decode:
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_get(20)
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_get(20): got connid=1001
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_read(20): checking
for input on id=1001
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: op tag 0x42, time 1634861708
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: ber_get_next on fd 20 failed
errno=0 (Success)
Oct 21 17:15:08 ldap-dev-03 slapd[4335]: conn=1001 op=2 do_unbind
And then the connection is closed. Comparing that to the same search on
my 2.4 server:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: conn=1000 op=1 do_search
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: >>> dnPrettyNormal: <dc=cpp,dc=edu>
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <<< dnPrettyNormal:
<dc=cpp,dc=edu>, <dc=cpp,dc=edu>
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: SRCH "dc=cpp,dc=edu" 2 0
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: 0 0 0
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: filter: (uid=henson)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: attrs:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: ==> limits_get: conn=1000 op=1
self="[anonymous]" this="dc=cpp,dc=edu"
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <== limits_get: type=DN
match=ANONYMOUS
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_search
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_dn2entry("dc=cpp,dc=edu")
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_dn2id("dc=cpp,dc=edu")
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_dn2id: got id=0x1
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_entry_decode:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_entry_decode
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: search_candidates:
base="dc=cpp,dc=edu" (0x00000001) scope=2
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates
(objectClass)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [b49d1940]
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read: failed (-30798)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_equality_candidates:
id=0, first=0, last=0
The search on objectClass doesn't seem to return any records? It just
immediately jumps to the uid search:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates (uid)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [b49d1940]
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read: failed (-30798)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_equality_candidates:
id=0, first=0, last=0
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates (uid)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [6e61da89]
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read 1 candidates
It finds my record, does the memberUid look up, and immediately returns it:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: conn=1000
op=1 p=3
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: err=0
matched="" text=""
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => send_search_entry: conn 1000
dn="uid=henson,ou=user,dc=cpp,dc=edu"
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= send_search_entry: conn 1000
exit.
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: conn=1000
op=1 p=3
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: err=0
matched="" text=""
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_response: msgid=2
tag=101 err=0
After the record is returned, the connection is immediately closed
without looking at anything else:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_get(15)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_get(15): got connid=1000
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_read(15): checking
for input on id=1000
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: op tag 0x42, time 1634862796
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: ber_get_next on fd 15 failed
errno=0 (Success)
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: conn=1000 op=2 do_unbind
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_close: conn=1000 sd=15
So it looks like there is something weird going on with objectClass? I
do have an index on that:
index default eq
index entryCSN,objectClass,reqEnd,reqResult,reqStart
My configuration between 2.4 and 2.5 is pretty much identical. Any idea
why it might be fully traversing the directory looking for object class
matches?
On 10/21/2021 4:55 PM, Howard Chu wrote:
Paul B. Henson wrote:
Any thoughts on what might be going on or how I can debug it to track down
exactly what is causing it? There was obviously a lot more debug info in the
logs
that I didn't include, but none of it jumped out to me as "smoking gun".
Try the search again with -d5. Also include the lines showing which attribute
it's checking in the index.
e.g.:
6171fcb7.1be5a183 0x7f28b65fd640 search_candidates: base="dc=example,dc=com"
(0x00000001) scope=2
6171fcb7.1be5b227 0x7f28b65fd640 => mdb_equality_candidates (objectClass)
6171fcb7.1be5cfe4 0x7f28b65fd640 => key_read
6171fcb7.1be5e088 0x7f28b65fd640 mdb_idl_fetch_key: [b49d1940]
6171fcb7.1be5faff 0x7f28b65fd640 <= mdb_index_read: failed (-30798)
6171fcb7.1be60a00 0x7f28b65fd640 <= mdb_equality_candidates: id=0, first=0,
last=0
6171fcb7.1be61901 0x7f28b65fd640 => mdb_equality_candidates (sn)
6171fcb7.1be62f1a 0x7f28b65fd640 => key_read
6171fcb7.1be63fbf 0x7f28b65fd640 mdb_idl_fetch_key: [03915b69]
6171fcb7.1be659a9 0x7f28b65fd640 <= mdb_index_read 2 candidates
6171fcb7.1be66a94 0x7f28b65fd640 <= mdb_equality_candidates: id=2, first=8,
last=9
6171fcb7.1be68cae 0x7f28b65fd640 mdb_search_candidates: id=2 first=8 last=9
