Internal unindexed searches in syncrepl

[abbra]

On latest Fedora Rawhide test composes I see plenty of complains about partial unindexed searches from syncrepl plugin even though there are indexes defined for the attributes specified in the filter:

Logs for the compose test: https://openqa.fedoraproject.org/tests/722674#downloads

Typical errors in the log:

[15/Nov/2020:18:58:04.118737200 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=72)(targetuniqueid=cb0ce98a-279a11eb-b8b0c9d4-8de4b180))" etime=0.002251050 nentries=1  notes=U details="Partially Unindexed Filter"
[15/Nov/2020:18:58:04.136015700 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=73)(targetuniqueid=cb0ce98a-279a11eb-b8b0c9d4-8de4b180))" etime=0.002381400 nentries=1  notes=U details="Partially Unindexed Filter"
[15/Nov/2020:18:58:04.167502775 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=74)(targetuniqueid=cb0ce98a-279a11eb-b8b0c9d4-8de4b180))" etime=0.000606675 nentries=1  notes=U details="Partially Unindexed Filter"
[15/Nov/2020:18:58:04.187813900 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=74)(targetuniqueid=cb0ce98a-279a11eb-b8b0c9d4-8de4b180))" etime=0.000362425 nentries=1  notes=U details="Partially Unindexed Filter"
[15/Nov/2020:18:58:04.225106850 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=75)(targetuniqueid=cb0ce986-279a11eb-b8b0c9d4-8de4b180))" etime=0.001161925 nentries=1  notes=U details="Partially Unindexed Filter"
[15/Nov/2020:18:58:04.228923925 -0500] - ERR - log_result - Internal unindexed search: source (cn=server,cn=plugins,cn=config) search base="cn=changelog" filter="(&(changenumber>=75)(targetuniqueid=cb0ce986-279a11eb-b8b0c9d4-8de4b180))" etime=0.002395775 nentries=1  notes=U details="Partially Unindexed Filter"

If I'd look at the indexes for cn=changelog backend, the indexes for those two attributes are defined. Here is output from my local instance:

# dsconf IPA-TEST backend index list cn=changelog |egrep '(changenumber|targetuniqueid)'
dn: cn=changenumber,cn=index,cn=changelog,cn=ldbm database,cn=plugins,cn=config
cn: changenumber
dn: cn=targetuniqueid,cn=index,cn=changelog,cn=ldbm database,cn=plugins,cn=config
cn: targetuniqueid

[mreynolds389]

Are they indexed for equality? "eq" Can you provide the index entries from dse.ldif please? As I recall IPA used to use an invalid format for the index types (I'm sure that's been corrected, but I'd like to confirm it).

Do you see the index files under /var/lib/dirsrv/slapd-INST/db/changelog/ ? If not, please "reindex" those indexes...

[abbra]

# dsconf IPA-TEST backend index list cn=changelog |egrep -A6 '(changenumber|targetuniqueid)'
dn: cn=changenumber,cn=index,cn=changelog,cn=ldbm database,cn=plugins,cn=config
cn: changenumber
nsIndexType: eq
nsMatchingRule: integerOrderingMatch
nsSystemIndex: false
objectClass: top
objectClass: nsIndex

--
dn: cn=targetuniqueid,cn=index,cn=changelog,cn=ldbm database,cn=plugins,cn=config
cn: targetuniqueid
nsIndexType: eq
nsSystemIndex: false
objectClass: top
objectClass: nsIndex

and

 ls -la /var/lib/dirsrv/slapd-IPA-TEST/db/changelog/
total 680
drwx------. 2 dirsrv dirsrv   4096 Nov 10 09:02 .
drwxrwx---. 5 dirsrv dirsrv   4096 Nov 15 15:31 ..
-rw-------. 1 dirsrv dirsrv  16384 Nov 10 09:02 aci.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 ancestorid.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 changenumber.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 10 09:00 cn.db
-rw-------. 1 dirsrv dirsrv     51 Nov 15 15:31 DBVERSION
-rw-------. 1 dirsrv dirsrv  57344 Nov 15 15:36 entryrdn.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 entryusn.db
-rw-------. 1 dirsrv dirsrv 434176 Nov 15 15:36 id2entry.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 nsuniqueid.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 numsubordinates.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 objectclass.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 parentid.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 10 08:59 seeAlso.db
-rw-------. 1 dirsrv dirsrv  16384 Nov 15 15:36 targetuniqueid.db

[mreynolds389]

Does dbscan return anything?

dbscan -f /var/lib/dirsrv/slapd-IPA-TEST/db/changelog/changenumber.db
dbscan -f /var/lib/dirsrv/slapd-IPA-TEST/db/changelog/targetuniqueid.db

[abbra]

Yes, it does. The values, of course, are different to what is in the original report as this is different system but nevertheless, it is working FreeIPA deployment:

[root@master ~]# dbscan -f /var/lib/dirsrv/slapd-IPA-TEST/db/changelog/changenumber.db
=209                                    
[root@master ~]# dbscan -f /var/lib/dirsrv/slapd-IPA-TEST/db/changelog/targetuniqueid.db
=882eba01-233311eb-8af0f60b-00866b2b    

[mreynolds389]

Yes, it does. The values, of course, are different to what is in the original report as this is different system but nevertheless, it is working FreeIPA deployment:

Thanks for checking! I'm assuming this system is also generating those error messages?

Anyway I was really hoping it was a config/timing issue :-) We'll look into this soon...

[Firstyear]

@mreynolds389 It could be that there is an internal filter transform that is occuring that has an un-indexed filter component we aren't logging.

[mreynolds389]

c1926df..357c16c 389-ds-base-1.4.4 -> 389-ds-base-1.4.4

18271ba..e762f35 389-ds-base-1.4.3 -> 389-ds-base-1.4.3

[mreynolds389]

https://bugzilla.redhat.com/show_bug.cgi?id=1951020