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