389-ds-base

#50252 Ticket 49372 - filter optimisation improvements for common queries
Closed by spichugi. Opened by firstyear.
firstyear/389-ds-base 50073-enable-filter-opt  into  master

Download 50252.patch

Bug Description: Due to the way we apply indexes to searches
and the presence of the "filter test threshold" there are a number
of queries which can be made faster if they understood the internals
of our idl_set and index mechanisms. However, instead of expecting
application authors to do this, we should provide it.

Fix Description: In the server we have some cases we want to
achieve, and some to avoid:

  • If a union has an unindexed candidate, we throw away all work
    and return an ALLIDS idls.
  • In an intersection, if we have an idl that is less than
    filter test threshold, we return immediately that idl
    rather than accessing all others, and perform a filter
    test.

Knowing these two properties, we can now look at improving filters
for queries.

In a common case, SSSD will give us a query which is a union of
host cn and sudoHost rules. However, the sudoHost rules are
substring searchs that are not able to be indexed - thus the whole
filter becomes an unindexed search. IE:

(|(cn=a)(cn=b)(cn= ....)(sudoHost=[]))

So in this case we want to move the substring to the first query
so that if it's un-indexed, we fail immediately with ALLIDS rather
than opening the cn index.

For intersection, we often see:

(&(objectClass=account)(objectClass=posixAccount)(uid=william))

The issue here is that the idls for account and posixAccount both
may contain 100,000 items. Even with idl lookthrough limits, until
we start to read these, we don't know if we will exceed that.

A better query is:

(&(uid=william)(objectClass=account)(objectClass=posixAccount))

Because the uid=william index will contain a single item, this
put's us below filter test threshold, and we will not open the
objectClass indexes.

In fact, in an intersection, it is almost always better to perform
simple equalities first:

(&(uid=william)(modifyTimestamp>=...)(sn=br*)(objectClass=posixAccount))

In most other cases, we will not greatly benefit from re-arrangement
due to the size of the idls involved we won't hit filter test. IE

(&(modifyTimestamp>=...)(sn=br*)(objectClass=posixAccount))

Would not be significantly better despite and possible arrangement
without knowing the content of sn.

So in summary, our rules for improving queries are:

  • unions-with-substrings should have substrings first
  • intersection-with-equality should have all non-objectclass
    equality filters first.

https://pagure.io/389-ds-base/issue/49372
https://pagure.io/389-ds-base/issue/50073

Author: wibrown

Original Review by: lkrispen, mreynolds (Thanks!)
Review by: ???

Other things to note: this fixes a lot of issues with the filter tests. The filter tests would fail even without the optimiser. This passes all tests with and without the filter optimiser active. It likely relies on @lkrispen onelevel scope fix.

Hey @mreynolds Did you want to take a look at this :)

@mreynolds Review reminder please :)

@mreynolds Review reminder please :)

I need to get this patch tested by FreeIPA team as they were the ones who found the original regression. I'll look into now...

This patch breaks the freeipa install, gathering logs of successful and failed installs

Wat, how? The optimiser is disabled ... :S

Thanks for that, but the logs don't help me much, I think that IPA attempts to cleanup after the failure. I'm going back to the patch to reexamine what's occuring.

rebased onto 9983d780646b18955fea58819a29250931f67ce3

Hey @mreynolds, I've updated this with an improvement to how we log the results in access log. The new output is:

[14/Mar/2019:10:37:40.373884600 +1000] conn=1 op=21 SRCH base="dc=example,dc=com" scope=2 filter="(cn:caseExactIA5Match:=ext-test-entry)" attrs=ALL
[14/Mar/2019:10:37:40.374433300 +1000] conn=1 op=21 RESULT err=0 tag=101 nentries=1 etime=0.0000976100 notes=U filter="(|(objectclass=referral)(cn:caseExactIA5Match:=ext-test-entry))"

Notice we now provide the optimised (executed) filter into the RESULT string, for comparison against the SRCH string. I think a single IPA install with this updated patch should be enough to try and diagnose what's going wrong, provided we can isolate the failing query in the access log. Is it possible to get the ipa install log as well when we do this test?

So on reconsideration as well, this patch has the optimiser disabled, but it does alter the behaviour of the referral and parentid construction for filters, which may or may not be related to the issue here.

Sorry didn't read everything over, but I had them triple check your patch vs no patch and it always failed after I applied your patch,. So its impacting something even though its disabled... very weird.

No problem, this is why I provided extra debugging info in latest patch to try and determine the cause. There is no filter optimisation, but there are changes to the referral and onelevel filter constructions, so I want to see if those are the cause by getting the extra details :)

@mreynolds Did we ever get this build checking with IPA? I'm happy to rebase/update it ...

Yo @mreynolds did we ever get anywhere with IPA on this? This would be a great change for them as it helps with SSSD' bad query generation.

rebased onto 2b4e0029fce85bfe6523cae95e923d7655b1a594

Yo @mreynolds did we ever get anywhere with IPA on this? This would be a great change for them as it helps with SSSD' bad query generation.

Sorry @firstyear I need to put a build together for them to retest. I will try to get to that today...

So @mreynolds helpfully linked me to a BZ where this filter optmiser caused an issue. I have taken the two queries, and then put them into a test search, to see what this would do to re-arrange these.

The original queries are :

working:

"(&(|(usercertificate;binary=0\82\03\AD0\82\02\95\A0\03\02\01\02\02\01\130\0D\06\09\2A\86H\86\F7\0D\01\01\0B\05)(ipaCertMapData=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1))(objectClass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))"

failing:

"(&(|(usercertificate;binary=0\82\03\AD0\82\02\95\A0\03\02\01\02\02\01\130\0D\06\09\2A\86H\86\F7\0D\01\01\0B\05)(ipaCertMapData=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)(altsecurityidentities=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1))(objectClass=posixAccount)(uid=*)(&(uidNumber=*)(!(uidNumber=0))))"

The results are as follows - note I have trimmed the binary output in these comparisons for ease of viewing, but they do match. 

(onelevel, working)
original
        (&
            (|
                (usercertificate;binary=)
                (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            )
            (objectClass=posixAccount)
            (uid=*)
            (&
                (uidNumber=*)
                (!
                    (uidNumber=0)
                )
            )
        )
optimised
(&
    (parentid=1)
    (|
        (objectclass=referral)
        (&
            (|
                (usercertificate;binary=)
                (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            )
            (objectClass=posixAccount)
            (uid=*)
            (uidNumber=*)
            (!
                (uidNumber=0)
            )
        )
    )
)
-------------------
(onelevel, failing)
original
        (&
            (|
                (usercertificate;binary=)
                (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
                (altsecurityidentities=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            )
            (objectClass=posixAccount)
            (uid=*)
            (&
                (uidNumber=*)
                (!
                    (uidNumber=0)
                )
            )
        )
optimised
(&
    (parentid=1)
    (|
        (objectclass=referral)
        (&
            (|
                (usercertificate;binary=)
                (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
                (altsecurityidentities=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            )
            (objectClass=posixAccount)
            (uid=*)
            (uidNumber=*)
            (!
                (uidNumber=0)
            )
        )
    )
)
-------------------
(subtree, working)
original
    (&
        (|
            (usercertificate;binary=)
            (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
        )
        (objectClass=posixAccount)
        (uid=*)
        (&
            (uidNumber=*)
            (!
                (uidNumber=0)
            )
        )
    )
optimised
(|
    (objectclass=referral)
    (&
        (|
            (usercertificate;binary=)
            (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
        )
        (objectClass=posixAccount)
        (uid=*)
        (uidNumber=*)
        (!
            (uidNumber=0)
        )
    )
)
-------------------
(subtree, failing)
original
    (&
        (|
            (usercertificate;binary=)
            (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            (altsecurityidentities=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
        )
        (objectClass=posixAccount)
        (uid=*)
        (&
            (uidNumber=*)
            (!
                (uidNumber=0)
            )
        )
    )
optimised
(|
    (objectclass=referral)
    (&
        (|
            (usercertificate;binary=)
            (ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
            (altsecurityidentities=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=ipauser1)
        )
        (objectClass=posixAccount)
        (uid=*)
        (uidNumber=*)
        (!
            (uidNumber=0)
        )
    )
)

It appears that only a single change is occuring, which is the (&) fold bringing (&(uidNumber=*)(!(uidNumber=0))) into the higher scope. If anyone can see anything else wrong here, I'd be keen to know, but I can't observe any other faults in the operation of the optimiser in these queries that would lead to absent results.

I think the issue might have been how you changed ACI processing on filters - not the actual candidate list.

Anyway, the current patch passes IPA tests, but the feature is "off". I'm going to do a build with the it "on" and see if it still fails...

I think the issue might have been how you changed ACI processing on filters - not the actual candidate list.
Anyway, the current patch passes IPA tests, but the feature is "off". I'm going to do a build with the it "on" and see if it still fails...

It still fails when enabled, just an FYI. Is there any other information you want me to get? Or run it again with a log level? Or debug patch?

Just the access log is fine (and the ipa install log) - the current branch here has a debug patch added that printes the "optimised" filter after the results so we can compare what transforms occured that may have caused the error. Thank you very much! :)

So if it passes when it's "off", you mean the #define in the filter.c? And it fails when that is #defined? That is "good" because it really narrows down where the fault could be (also also means we can probably commit this with some confidence that we can back out if needed by flipping the #define)

Just the access log is fine (and the ipa install log) - the current branch here has a debug patch added that printes the "optimised" filter after the results so we can compare what transforms occured that may have caused the error. Thank you very much! :)

I'll get the access log, no error log?

So if it passes when it's "off", you mean the #define in the filter.c? And it fails when that is #defined?

Yeah I just uncommented the define and it failed the same way it did originally when I had to revert the patch.

@mreynolds Great thanks! I have all the info you sent me so I'll investigate this soon! (I have so much email after my tropical week off).

https://lists.fedoraproject.org/archives/list/389-devel@lists.fedoraproject.org/thread/545CSBD4OY3RGUDTSL37J7FYXFEAW63H/ <<-- write here of investigation and possible conclusions.

rebased onto e2048f237f53809370ec51e3e91b8bed8fdc0258

@mreynolds I have updated this patch to harden the filter bypass flag application in subtree candidates, and improved logging of LOG_FILTER. The filter opt is disabled.

So I'm wondering what's the right way to proceed here. I think we could commit this into master, given that the optimiser is disabled, and that's what causes the problem. Then we at least have the "good" parts of the patch related to the tombstone and referral application cleaned up. We also get some better debuging of filter application for this.

Who have you been working with in RH QE about this? I think I need to know exactly what query IPA is failing with, and the exact conditions, maybe better, we need LOG_FILTER enabled too.

What do you think?

1 new commit added

  • DEBUG BUILD

The benefit of the patch is perf improvement (10 times faster) but with specific conditions (filters and entries)
The drawbacks are that it is difficult to review (low level routine with multiple potential impact) and test as many regression were discovered after QE

IMHO it worth getting the improvement in master if the known problematic use cases are fixed. here is a list of them mentioned in the ticket (but it may exist others not listed in the ticket :( )

  • 48252
  • 48265
  • 1616412
  • 48275
  • 49617

@tbordaz Part of the issue is that no one has provided sufficient information about what query is going wrong, only that something does.

I have attempted an ipa install with a debug build which fails, for the reason:

2019-04-30T05:08:35Z DEBUG stderr=kdb5_util: Kerberos database constraints violated while adding entries to the database

There is no further krb logs or information provided about this matter (which I find quite stunning ....).

However, it appears that this entry already exists, and KRB is "double-adding" it, which seems to be the fault of the extra debugging info slowing down the process. So I'm probably going to try to speed up the errorlog to that the install can proceed....

EDIT: ramdisk fixes this right up ;)

Edited by firstyear 
The ipa-server-install command was successful

So with a debug build I can successfully install IPA. I have kept all associated logs.

@mreynolds or @tbordaz who in RH QE from IPA has been reporting these failures recently when they have attempted installations? I'd like to contact them to ask about what steps they took, and their method so I can attempt to reproduce.

1 new commit added

  • More debugging

1 new commit added

  • More debugging

1 new commit added

  • More debugging

1 new commit added

  • More debugging

@firstyear, we need to wait (next week) for @mreynolds to confirm which failures he discovered https://pagure.io/389-ds-base/pull-request/50252#comment-83964.

Have you been able to verify the patch against the known problematic use cases (https://pagure.io/389-ds-base/pull-request/50252#comment-84875) ?

@tbordaz I've done one better! I got in touch with someone at RH QE and have reproduction cases. I'm currently analysing the system now, and may have finally had a break through on this. I'm working a bit late to finalise some of the report on the matter. :)

1 new commit added

  • More debugging

Hey @tbordaz

Before I sign out for the night, I believe the issue is that the filter optimiser is causing the query to evaluate correctly - specifically, the certmap query fails due to a lack of aci allowing read to altsecurityidentities, which causes the OR condition to fail etc.

More curious is why this does not fail when the optimiser is off - I suspect that there may be some issue related to filter test bypassing, so I'm going to suggest we set the filter test bypass to "off" with an IPA install to determine if that also affects it.

I have more logging and details related to this, which I'll write up nicer for the ticket tomorrow.

Thanks :)

Hi everyone,

Here is my analysis of the issue that has occurred with filter optimisation and why the queries were reporting failure.

The main issue was related to a query in the ipa certificate mapping functionality that interacts with SSSD. The query in question that was failing was:

(&
    (|
        (usercertificate;binary=)
        (ipaCertMapData=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1)
        (altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1)
    )
    (objectClass=posixAccount)
    (uid=*)
    (&
        (uidNumber=*)
        (!
            (uidNumber=0)
        )
    )
)

Please note this has been formatted for ease of understanding.

I have added a large amount of debbuging info into a build, and using a ramdisk for logging to ensure adequate performance for the error log. I also set the server to single threaded to guarantee that the queries were linearised in logs, IE no interleaved or interfering data.

In this log I have noted that the filter optimisers behaviour is correct - the translated query is:

(|
    (objectClass=referral)
    (&
        (|
            (usercertificate;binary=...)
            (ipaCertMapData=x509:<i>o=dev.blackhats.net.au,cn=certificate authority<s>o=dev.blackhats.net.au,cn=ipauser1)
            (altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1)
        )
        (objectClass=posixaccount)
        (uid=*)
        (uidNumber=*)
        (!
            (uidNumber=0)
        )
    )
)

This is logically equivalent.

I have also noted the correct behaviour of the filter being applied. The log section here is relevant - note that I have partially annotated it for ease of understanding:

[02/May/2019:14:21:53.791733201 +1000] - DEBUG - filter_candidates_ext -        OR            (| ... )
[02/May/2019:14:21:53.791765725 +1000] - DEBUG - list_candidates - => 0xa1
[02/May/2019:14:21:53.791781631 +1000] - DEBUG - filter_candidates_ext -        EQUALITY      (objectClass=referral)
[02/May/2019:14:21:53.791798745 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - =>
[02/May/2019:14:21:53.791931255 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - => 0
[02/May/2019:14:21:53.792128141 +1000] - DEBUG - filter_candidates_ext - <= IDL length(0)     (objectClass=referral) -> 0 candidates
[02/May/2019:14:21:53.792164718 +1000] - DEBUG - list_candidates - NOT applying union shortcut
[02/May/2019:14:21:53.792180518 +1000] - DEBUG - filter_candidates_ext -        AND           (& ... )
[02/May/2019:14:21:53.792195995 +1000] - DEBUG - list_candidates - => 0xa0
[02/May/2019:14:21:53.792359316 +1000] - DEBUG - filter_candidates_ext -        OR            (| ... )
[02/May/2019:14:21:53.792408848 +1000] - DEBUG - list_candidates - => 0xa1
[02/May/2019:14:21:53.792435839 +1000] - DEBUG - filter_candidates_ext -        EQUALITY      (userCertificate;binary=...)
[02/May/2019:14:21:53.792587334 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - =>
[02/May/2019:14:21:53.792623904 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - => 0
[02/May/2019:14:21:53.792980957 +1000] - DEBUG - filter_candidates_ext - <= IDL length(0)     (userCertificate;binary=...) -> 0 candidates
[02/May/2019:14:21:53.793015546 +1000] - DEBUG - list_candidates - NOT applying union shortcut      NO ALLIDS present, continue
[02/May/2019:14:21:53.793030057 +1000] - DEBUG - filter_candidates_ext -        EQUALITY      (ipaCertMapData=...)
[02/May/2019:14:21:53.793046839 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - =>
[02/May/2019:14:21:53.793155068 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - => 0
[02/May/2019:14:21:53.793200212 +1000] - DEBUG - filter_candidates_ext - <= IDL length(486)   (ipaCertMapData=...) -> ALLIDS
[02/May/2019:14:21:53.793214719 +1000] - DEBUG - list_candidates - union shortcut                   ALLIDS present, OR must fail as ALLIDS
[02/May/2019:14:21:53.793232658 +1000] - DEBUG - list_candidates - <= 0xa1 IDL length(486)
[02/May/2019:14:21:53.793331383 +1000] - DEBUG - filter_candidates_ext - <= IDL length(486)   (| ... ) -> ALLIDS
[02/May/2019:14:21:53.793388053 +1000] - DEBUG - list_candidates - NOT applying intersection shortcut (filter test threshold)   (& ... ) cand len > filter test, do not shortcut
[02/May/2019:14:21:53.793423332 +1000] - DEBUG - filter_candidates_ext -        EQUALITY      (objectClass=posixAccount)
[02/May/2019:14:21:53.793622612 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - =>
[02/May/2019:14:21:53.793790387 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - => 0
[02/May/2019:14:21:53.793885354 +1000] - DEBUG - filter_candidates_ext - <= IDL length(2)     (objectClass=posixAccount) -> 2 candidates
[02/May/2019:14:21:53.794038943 +1000] - DEBUG - list_candidates - intersection shortcut (filter test threshold)    (& ... ) a cand len is < filter test, shortcut return partial set. Set do not bypass flag.
[02/May/2019:14:21:53.814965251 +1000] - DEBUG - list_candidates - <= 0xa0 IDL length(2)     (& ... ) -> 2 candidates (partial)
[02/May/2019:14:21:53.815077254 +1000] - DEBUG - filter_candidates_ext - <= IDL length(2)
[02/May/2019:14:21:53.815102562 +1000] - DEBUG - list_candidates - NOT applying union shortcut
[02/May/2019:14:21:53.815650798 +1000] - DEBUG - list_candidates - <= 0xa1 IDL length(2)     (| ... ) -> 2 candidates (partial)
[02/May/2019:14:21:53.815665087 +1000] - DEBUG - filter_candidates_ext - <= IDL length(2)
[02/May/2019:14:21:53.816754671 +1000] - DEBUG - ldbm_back_next_search_entry_ext - Applying filter test     do not bypass flag is set, enforce filter test on partial candidate set.

At this point the partial candidate set has two items = uid=admin and uid=ipauser1

The filter test now begins, and while applying to uid=admin, the following failure occurs:

[02/May/2019:20:53:21.834989302 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (|(objectClass=referral)(&(|(usercertificate;binary=0<82>^D*0<82>^C^R<A0>^C^B^A^B^B^A^K0^M^F      *<86>H<86><F7>^M^A^A^K^E)(ipaCertMapData=x509:<i>o=dev.blackhats.net.au,cn=certificate authority<s>o=dev.blackhats.net.au,cn=ipauser1)(altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1))(objectClass=posixaccount)(uid=*)(uidNumber=*)(!(uidNumber=0)))) on uid=ipauser1,cn=users,cn=accounts,dc=dev,dc=blackhats,dc=net,dc=au
...
[02/May/2019:20:53:21.845422033 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1) on uid=ipauser1,cn=users,cn=accounts,dc=dev,dc=blackhats,dc=net,dc=au
...
[02/May/2019:20:53:21.847993991 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 50 -> (altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1) on uid=ipauser1,cn=users,cn=accounts,dc=dev,dc=blackhats,dc=net,dc=au
...
[02/May/2019:20:53:21.861400976 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt -1 -> (|(objectClass=referral)(&(|(usercertificate;binary=0<82>^D*0<82>^C^R<A0>^C^B^A^B^B^A^K0^M^F      *<86>H<86><F7>^M^A^A^K^E)(ipaCertMapData=x509:<i>o=dev.blackhats.net.au,cn=certificate authority<s>o=dev.blackhats.net.au,cn=ipauser1)(altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1))(objectClass=posixaccount)(uid=*)(uidNumber=*)(!(uidNumber=0)))) on uid=ipauser1,cn=users,cn=accounts,dc=dev,dc=blackhats,dc=net,dc=au
...
==> /var/log/dirsrv/slapd-DEV-BLACKHATS-NET-AU/access <==
[02/May/2019:20:53:21.861772973 +1000] conn=27 op=13 RESULT err=0 tag=101 nentries=0 etime=0.0086440389 notes=U filter="(|(objectclass=referral)(&(|(usercertificate;binary=0<82>^D*0<82>^C^R<A0>^C^B^A^B^B^A^K0^M^F    *<86>H<86><F7>^M^A^A^K^E)(ipaCertMapData=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1)(altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1))(objectClass=posixAccount)(uid=*)(uidNumber=*)(!(uidNumber=0))))"

This is the important part - 'filt 50' is an rc of 50 - insufficient access. It is now important to understand who has bound:

[02/May/2019:20:52:55.275409924 +1000] conn=27 fd=106 slot=106 connection from 172.24.15.14 to 172.24.15.14
[02/May/2019:20:52:55.282769356 +1000] conn=27 op=0 SRCH base="" scope=0 filter="(objectClass=*)" attrs="* altServer namingContexts supportedControl supportedExtension supportedFeatures supportedLDAPVersion supportedSASLMechanisms domaincontrollerfunctionality defaultnamingcontext lastusn highestcommittedusn aci"
[02/May/2019:20:52:55.308091966 +1000] conn=27 op=0 RESULT err=0 tag=101 nentries=1 etime=0.0027247181 filter="(objectClass=*)"
[02/May/2019:20:52:55.669078776 +1000] conn=27 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[02/May/2019:20:52:55.698373098 +1000] conn=27 op=1 RESULT err=14 tag=97 nentries=0 etime=0.0029494522, SASL bind in progress
[02/May/2019:20:52:55.698801574 +1000] conn=27 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[02/May/2019:20:52:55.715020675 +1000] conn=27 op=2 RESULT err=14 tag=97 nentries=0 etime=0.0016721784, SASL bind in progress
[02/May/2019:20:52:55.715256927 +1000] conn=27 op=3 BIND dn="" method=sasl version=3 mech=GSSAPI
[02/May/2019:20:52:55.759796551 +1000] conn=27 op=3 RESULT err=0 tag=97 nentries=0 etime=0.0044839201 dn="fqdn=test-c.dev.blackhats.net.au,cn=computers,cn=accounts,dc=dev,dc=blackhats,dc=net,dc=au"

It is the machine account of the DC.

When performing the following search as uid=admin, this works:

ldapsearch '(&(|(altsecurityidentities=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1)(ipaCertMapData=X509:<I>O=DEV.BLACKHATS.NET.AU,CN=Certificate Authority<S>O=DEV.BLACKHATS.NET.AU,CN=ipauser1))(objectClass=posixAccount)(uid=*)(uidNumber=*)(!(uidNumber=0)))'

As a result, I can confirm, that the issue is not within the filter optimiser - the issue is the lack of access control allow machine accounts to read the altsecurityidentities attribute.

Now there are some important follow ups here:

  • That the server accepts a filter which contains invalid syntax elements, instead of rejecting it.
  • altsecurityidentities is NOT in the schema, and is invalid for searches within the directory. This would also lead to fully un-indexed searches.
  • ipaCertMapData is NOT indexed, causing all certmap queries using it to effectively be un-indexed.
  • Logging data around filter application is insufficent, which led to IPA/DS QE being unable to diagnose this issue for a long period of time.
  • The logging system of DS was not performant enough to allow debugging to occur without mounting ramdisks to log areas.
  • The log data was interleaved and lacked identifiers to associate it to the operation, further hindering correct analysis.

As this issue has been open for such a long time I think it's important we follow up on the various, and complex causes that have delayed a proper analysis of this issue. For example, had we of implemented point 1, and rejected the query, we would never have seen this query leave a development environment, and likely would have been identified faster as failing. Similar, proper logging and confidence to enable it, would have allow IPA QE to much quicker diagnose the issue's location to the IPA ACI's, rather than being affected by the DS query optimiser. And finally, our own confidence to enable and understand log data as a team, to make better determinations.

As a result of this issue I plan to open a number of issues:

  • FreeIPA should have an ACI to cover the altsecurityidentities field and relevant schema, or it should be removed from all supporting applications.
  • FreeIPA should index ipaCertMapData.
  • 389DS should default to filter bypass test off. There is no situation where correctness should be overlooked for the benefit of performance.
  • 389DS should enforce that all attributes of a filter are present in schema, and if not, the filter is rejected. This should have a libglobs.c flag, default to "enforcing".
  • 389DS must improve it's logging system performance - for access and error logs.
  • 389DS logs must be re-architected, such that during an operation a "op log" structure is built, and at the conclusion of the op it is submitted as a whole single unit, where it's written to the log as a structured and isolated whole.
  • 389DS filter optimise should have a libglobs.c flag for cn=config to avoid a costly revert and rebuild cycle to analyse.

These changes, would have prevented and assisted this issue to be resolved much sooner, and much faster.

Thanks,

Here are all relevant and opened issues.

https://pagure.io/389-ds-base/issue/50349 <<-- filter schema checking
https://pagure.io/389-ds-base/issue/50350 <<-- logging structure
https://pagure.io/389-ds-base/issue/49415 <<-- log performance
https://pagure.io/389-ds-base/issue/50348 <<-- filter bypass default to off.
https://pagure.io/freeipa/issue/7933 <<-- IPA unindexed attrs
https://pagure.io/freeipa/issue/7932 <<-- IPA missing altsecurityidentities

I will update this patch to cleanup much of the debugging, and to add the libglobs.c flag for enable/disable of the filter rather than being a compile flag.

@firstyear thanks for the investigation. I think some of your suggestions are sound but not all.

I want to focus on your proposal to remove unknown schema elements from all supporting applications. This is pretty much impossible to achieve and expect.

In case of certificate mapping rules FreeIPA, the same set of rules can apply to multiple sources. SSSD runs the resulting search against all its databases where a user can be defined. In practice, it means that the same filter is applied to both IPA LDAP and AD LDAP in case of a trust to active directory established in FreeIPA.

altSecurityIdentities is an attribute defined by AD LDAP schema, not FreeIPA. While we can add the element to our schema, it makes little difference: no objects in IPA LDAP are going to have this attribute defined. Sure, it will help 389-ds to short-circuit the search thanks to indexing of this element and I have submitted https://github.com/freeipa/freeipa/pull/3110

I don't think it is realistically possible to enforce that all attributes of a filter are present in schema and reject the filter otherwise. RFC 4511 section 4.5.1.7. states that

Servers MUST NOT return errors if attribute descriptions or matching rule ids are not recognized, assertion values are invalid, or the assertion syntax is not supported. More details of filter processing are given in Clause 7.8 of [X.511].

and Clause 7.8 of https://www.itu.int/rec/dologin_pub.asp?lang=e&id=T-REC-X.511-201610-I!!PDF-E&type=items has this language:

Any assertion about the values of such an attribute is only defined if the AttributeType is known by the evaluating mechanism, the purported AttributeValue(s) conforms to the attribute syntax defined for that attribute type, the implied or indicated matching rule is applicable to that attribute type, and (when used) a presented matchValue conforms to the syntax defined for the indicated matching rules. When these conditions are not met, the FilterItem shall evaluate to the logical value UNDEFINED.
An assertion which is defined by these conditions additionally evaluates to UNDEFINED if it relates to an attribute value and the attribute type is not present in an attribute against which the assertion is being tested. An assertion which is defined by these conditions and relates to the presence of an attribute type evaluates to FALSE.

@firstyear thanks for the investigation. I think some of your suggestions are sound but not all.
I want to focus on your proposal to remove unknown schema elements from all supporting applications. This is pretty much impossible to achieve and expect.

It is a security risk for DOS due to the fact it can never be indexed. That alone is worth following up, let alone human interaction elements.

In case of certificate mapping rules FreeIPA, the same set of rules can apply to multiple sources. SSSD runs the resulting search against all its databases where a user can be defined. In practice, it means that the same filter is applied to both IPA LDAP and AD LDAP in case of a trust to active directory established in FreeIPA.
altSecurityIdentities is an attribute defined by AD LDAP schema, not FreeIPA. While we can add the element to our schema, it makes little difference: no objects in IPA LDAP are going to have this attribute defined. Sure, it will help 389-ds to short-circuit the search thanks to indexing of this element and I have submitted https://github.com/freeipa/freeipa/pull/3110

If it's in 389, define it in schema else you will ALWAYS have this search become un-indexed and full table scan, and fail security checks. It is not possible for you to leave this outside of schema, and have it perform correctly.

If it's not going to be present in 389-ds, don't search for it, and then you won't care if the filter enforces attributes.

I don't think it is realistically possible to enforce that all attributes of a filter are present in schema and reject the filter otherwise. RFC 4511 section 4.5.1.7. states that

Servers MUST NOT return errors if attribute descriptions or matching rule ids are not recognized, assertion values are invalid, or the assertion syntax is not supported. More details of filter processing are given in Clause 7.8 of [X.511].

and Clause 7.8 of https://www.itu.int/rec/dologin_pub.asp?lang=e&id=T-REC-X.511-201610-I!!PDF-E&type=items has this language:

Any assertion about the values of such an attribute is only defined if the AttributeType is known by the evaluating mechanism, the purported AttributeValue(s) conforms to the attribute syntax defined for that attribute type, the implied or indicated matching rule is applicable to that attribute type, and (when used) a presented matchValue conforms to the syntax defined for the indicated matching rules. When these conditions are not met, the FilterItem shall evaluate to the logical value UNDEFINED.
An assertion which is defined by these conditions additionally evaluates to UNDEFINED if it relates to an attribute value and the attribute type is not present in an attribute against which the assertion is being tested. An assertion which is defined by these conditions and relates to the presence of an attribute type evaluates to FALSE.

I do not believe we should be so narrow in our view, when an rfc defined many years ago, is limiting us and presenting security risks, and performance risks. Had we of enforced this behavior, the certmap flaws would never have reached a production codebase, would have told our developers that a mistake was made, and would have aided us as humans to make informed decisions.

Additionally, it's a false argument to claim that any server is LDAP complaint, besides OpenLDAP - we certainly have our share of flaws and quirks that make us odd, and so to bring in the RFC here for "correctness" is not a really strong argument here IMO.

I think you also presenting your argument in a way that does not consider human behavior, and I do not agree with it. It's my job to do what is best for the 389-ds project. As a result, my recommendation remains - we should act in a manner that respects and helps humans make correct, informed decisions, and adds constraints to prevent security and performance risks. If we were to implement this feature, IPA would have the choice to disable it to maintain compatability - and that's your choice you are free to make.

389-ds is free to ignore any user-provided input, including filters which reference unknown attributes. I think this doesn't contradict RFC 4511. However, it is not reasonable to directly contradict RFC 4511 by returning an error to such search. May be you were implying a different response but with the statement

389DS should enforce that all attributes of a filter are present in schema, and if not, the filter is rejected.

is what I read out of it.

From FreeIPA side we have no control over which certmap rules users would add to the system. We can suggest but the reality is that FreeIPA here is a centralized storage of those rules and SSSD is applying them, not FreeIPA. It might be possible to differentiate such searches on SSSD side between different domains and not sending it to search at IPA LDAP server, I don't know. This doesn't change a fact that such search might happen. altSecurityIdentities is just one of such attributes that used on AD side, there could be others. In any way, it is beyond what FreeIPA can control.

@sbose, is it possible to separate inside SSSD which certmap rule filters applied to what source domain? See above -- if we can avoid searching in IPA LDAP for attributes that clearly only apply on AD side, we could avoid the issues described in this 389-ds ticket.

Hi,

SSSD does not use altSecurityIdentities by default. It is coming from the certificate mapping and matching rules. The rules can be defined per domain with the help of the --domain option of ipa certmap-add to ipa certmap-mod. If the domain is missing the rule applies to the IPA domain.

HTH

bye,
Sumit

@firstyear, sorry to come late in that thread. Thanks for your great investigations.

ldap client are free to use any attribute in their filter. Now I am unsure what matching rule will be picked up if the attribute is unknown. The evaluation of the filter for building the candidate list leads to unindex with that unknown component but it is legal to put unindex component. The use of the filter for the candidate matching can hide some candidate if rights are not granted. I think it is allowed to specify unknown attribute in aci.

I agree that if the search fails because of the missing ACI, adding the ACI looks to appropriate fix.

Just a question, is this test successful without your patch ?

I've updated https://github.com/freeipa/freeipa/pull/3110 to provide following changes:

  • add altSecurityIdentities attribute to IPA LDAP schema
  • allow authenticated binds to read altSecurityIdentities attribute
  • index both ipacertmapdata and altsecurityidentities
  • add a check to ipa certmaprule-{add,mod} that will enforce adding altSecurityIdentities filter only to trusted Active Directory domains.

I've updated https://github.com/freeipa/freeipa/pull/3110 to provide following changes:

add altSecurityIdentities attribute to IPA LDAP schema
allow authenticated binds to read altSecurityIdentities attribute
index both ipacertmapdata and altsecurityidentities
add a check to ipa certmaprule-{add,mod} that will enforce adding altSecurityIdentities filter only to trusted Active Directory domains.

Great, this sounds like it will resolve a lot of the issues.

@firstyear, sorry to come late in that thread. Thanks for your great investigations.
ldap client are free to use any attribute in their filter. Now I am unsure what matching rule will be picked up if the attribute is unknown. The evaluation of the filter for building the candidate list leads to unindex with that unknown component but it is legal to put unindex component. The use of the filter for the candidate matching can hide some candidate if rights are not granted. I think it is allowed to specify unknown attribute in aci.

Well, there are two options.

  • We outright reject the filter
  • We mark the filter internally as invalid so we return IDL(0) instead of allids because it's not in schema.

There is a risk of breaking some installs that use extensibleObject though, so this behaviour would certainly need a flag in cn=config. But for the "correct" use case, this is the best action.

I agree that if the search fails because of the missing ACI, adding the ACI looks to appropriate fix.
Just a question, is this test successful without your patch ?

The test was also failing without the filter optimisation patch, so I think that people were pointing the finger at filter opt when the failure may have been elsewhere. I'm still trying to understand the past conditions, but I suspect some interaction with the previously failing onelevel search could be related. It's hard as I don't have the debug info needed in previous versions :(

This is why I think the best option for getting this feature advanced is to make a cn=config flag, and for now, default it to "off" and then gain confidence that the other changes are valid, then default to "on" later - it gives us an easy rollback and work around too.

rebased onto 2fae03ab15a03da153e21367e5ac01de41f356b8

Okay! This update cleans up the debugging from previous, adds a cn=config switch that currently defaults to off, and basically just tidies up the patch. I will propose the default to be ON in a seperate patch once IPA has landed the necessary changes and I have tested them.

Please review! (ping @mreynolds and @tbordaz especially about this :) )

I wiil (and want to) look into this, but can only do it next week, stay tuned

rebased onto 99778336b3d956ff735d7064e4a7329bb46b3c94

@lkrispen I know you want to look into this, and have probably been busy. I'm happy to wait for your expert eyes to look.

I think that I'd like this merged before I consider merge of https://pagure.io/389-ds-base/pull-request/50379 because this (filter opt) contains a number of fixes for filter verification tests, and I'd really like to be confident in those and have them in master before I merge the filter validation code. Too many changes in the one area too quickly could cause problems ...

summary - 50379 is blocked on this pr :)

I did not look at the patch itself, wanted to verify it before. But thze test cases for #48275 and #49617 fail. Both tickets have testcases and Thierry listed them in a comment above.

If you want to revise a patch which broke these before please ensure that they are not broken again.

Another question is: this patch claims to optimize queries, but is very complex and had and has side effects. Do we have data showing the performance improvements achieved with this change ?

@lkrispen I was under the impression that these were resolved in other ways, but I'll follow these up, integrate those test cases and investigate.

I previously did performance testing of this, but I'll run them again if that helps,

Thanks,

Hey there,

It looks like the test on 49617 was failing because some of the default aci and user layouts changed in 1.4. Altering the asserts to account for this, it appears to pass, but perhaps I have lost the intent of the test.

For 48275 I can see the following:

[23/May/2019:13:21:21.534673000 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt -1 -> (objectClass=referral) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.535656100 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (|(uid=user.1)(mail=user.xxxx1@example.com)) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.536651100 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - OR
[23/May/2019:13:21:21.537696300 +1000] - DEBUG - vattr_test_filter_list_or - =>
[23/May/2019:13:21:21.538711000 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (uid=user.1) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.539682200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:21:21.540687100 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (uid=user.1) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.541711200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (mail=user.xxxx1@example.com) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.542720200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:21:21.543724700 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 50 -> (mail=user.xxxx1@example.com) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.544789300 +1000] - DEBUG - vattr_test_filter_list_or - <= 1
[23/May/2019:13:21:21.545786300 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 50 -> (|(uid=user.1)(mail=user.xxxx1@example.com)) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com
[23/May/2019:13:21:21.546729400 +1000] - DEBUG - vattr_test_filter_list_or - <= -1
[23/May/2019:13:21:21.547701500 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt -1 -> (|(objectClass=referral)(|(uid=user.1)(mail=user.xxxx1@example.com))) on cn=user.1,ou=green_one,ou=testbase,dc=example,dc=com

It looks like the attribute "mail" is not allowed to be read, which is causing the filter application to fail on mail=user.xxxx1. Looking at the configured ACI's it would appear they do not allow mail to be read. This would be the cause of the failure (and itself may be an artifact of the changing default aci's between 1.3.x to 1.4.x.

There is no evidence in either case of filter optimisation causing failures or corruption to the query. It looks like this is again, aci related.

Hope that helps,

PS: I'm going to finish some tidy up, but I'll submit both tests along with this patch.

Indeed, my changes lost the meaning of the test. On review there is an issue, but it's not filter optimisation. It looks like onelevel searches are failing due to a missing read aci on parentid.

[23/May/2019:13:44:53.510329400 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (objectclass=posixaccount) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.511191000 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 50 -> (parentid=4) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.512104400 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (|(objectClass=referral)(uid=*)) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.512980200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - OR
[23/May/2019:13:44:53.513834600 +1000] - DEBUG - vattr_test_filter_list_or - =>
[23/May/2019:13:44:53.514655200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (objectClass=referral) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.515546800 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:44:53.516419600 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (objectclass=posixaccount) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.517261700 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:44:53.518189800 +1000] - DEBUG - test_ava_filter - =>
[23/May/2019:13:44:53.519100200 +1000] - DEBUG - plugin_call_syntax_filter_ava_sv - => objectclass=posixaccount
[23/May/2019:13:44:53.519943300 +1000] - DEBUG - plugin_call_syntax_filter_ava - <= 0
[23/May/2019:13:44:53.520763400 +1000] - DEBUG - test_ava_filter - <= 0
[23/May/2019:13:44:53.521584500 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (objectclass=posixaccount) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.522535100 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (objectClass=referral) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.523420800 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (objectClass=referral) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.524282800 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:44:53.525217700 +1000] - DEBUG - test_ava_filter - =>
[23/May/2019:13:44:53.526149400 +1000] - DEBUG - plugin_call_syntax_filter_ava_sv - => objectClass=referral
[23/May/2019:13:44:53.527029800 +1000] - DEBUG - plugin_call_syntax_filter_ava - <= -1
[23/May/2019:13:44:53.527878500 +1000] - DEBUG - test_ava_filter - <= -1
[23/May/2019:13:44:53.528710300 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt -1 -> (objectClass=referral) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.529635700 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (uid=*) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.530503600 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - PRESENT
[23/May/2019:13:44:53.531439800 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (objectclass=posixaccount) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.532333300 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - EQUALITY
[23/May/2019:13:44:53.533237100 +1000] - DEBUG - test_ava_filter - =>
[23/May/2019:13:44:53.534092000 +1000] - DEBUG - plugin_call_syntax_filter_ava_sv - => objectclass=posixaccount
[23/May/2019:13:44:53.534962400 +1000] - DEBUG - plugin_call_syntax_filter_ava - <= 0
[23/May/2019:13:44:53.535815900 +1000] - DEBUG - test_ava_filter - <= 0
[23/May/2019:13:44:53.536723700 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (objectclass=posixaccount) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.537578000 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (uid=*) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.538428200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - => processing filt -> (uid=*) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.539283000 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - PRESENT
[23/May/2019:13:44:53.540237200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (uid=*) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.541107900 +1000] - DEBUG - vattr_test_filter_list_or - <= 0
[23/May/2019:13:44:53.542076200 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 0 -> (|(objectClass=referral)(uid=*)) on uid=my_user,ou=people,dc=example,dc=com
[23/May/2019:13:44:53.542952500 +1000] - DEBUG - vattr_test_filter_list_and - <= 0
[23/May/2019:13:44:53.543891600 +1000] - DEBUG - slapi_vattr_filter_test_ext_internal - <= filt 50 -> (&(parentid=4)(|(objectClass=referral)(uid=*))) on uid=my_user,ou=people,dc=example,dc=com

This can be easily explained - the previous default aci on 1.3.x was "targetattr !=", which meant all system attrs were allowed to read.

Now on 1.4.x we limit that list to a set of controlled, known attrs we should allow to read. It would appear that in this process parentid was missed.

I think the correct fix could be to add parentid to the default list of allowed read attributes to resolve this issue, or to have a special exemption for parentid in slapi_vattr_filter_test_ext_internal

Indeed, my changes lost the meaning of the test. On review there is an issue, but it's not filter optimisation. It looks like onelevel searches are failing due to a missing read aci on parentid.

No. The problem occurs because filteroptimisation for onelevel searches adds the parentid component to the filter and then uses this extended fiter when testing access. But the use of parentid is an internal thing, the client did not request access and does not need to have it.

I think the correct fix could be to add parentid to the default list of allowed read attributes to resolve this issue, or to have a special exemption for parentid in slapi_vattr_filter_test_ext_internal

The correct fix is to use the original filter in testing access, and I think we had already a fix for this, but it was not applied because the filter opt patch was backed out.

@firstyear I am surprise by this missing aci.

IIRC when the filter optimization was introduced it added a filter component like (parentid=xx). freeipa team hit that missing aci and fixed it.

Is it missing in your patch or in default deployement ?

It looks like the attribute "mail" is not allowed to be read, which is causing the filter application to fail on mail=user.xxxx1. Looking at the configured ACI's it would appear they do not allow mail to be read. This would be the cause of the failure (and itself may be an artifact of the changing default aci's between 1.3.x to 1.4.x.

It is NOT about aci changes, with current master the test passes, with your patch applied it fails, no change in acis.

It is about handling filtercomponents with unknown attributes or attributes in OR filters. The intended behaviour is to ignore these components in or filters. We also had a CVE about different behaviour in changing return codes if these components did match or not, and the options were
1 - either request access to all attributes in the or filter or
2 - ignore or filter components completely and ensure that the result is the same as if they were not present.
1 was the original implementation, but after many requests from IPA and customers we changed to 2 - and we need to keep this behaviour

@firstyear I am surprise by this missing aci.

it is not about a missing aci

IIRC when the filter optimization was introduced it added a filter component like (parentid=xx). freeipa team hit that missing aci and fixed it.
Is it missing in your patch or in default deployement ?

IPA added this as a workaround until we fixed it, but after the backout of the filteopt patch, this fix was not committed.

In the ticket 49617 there is a patch, I didn't verify if it still fixes the new filteropt proposal

@firstyear I am surprise by this missing aci.

it is not about a missing aci

That's what the evidence was telling me ...

IIRC when the filter optimization was introduced it added a filter component like (parentid=xx). freeipa team hit that missing aci and fixed it.
Is it missing in your patch or in default deployement ?

IPA added this as a workaround until we fixed it, but after the backout of the filteopt patch, this fix was not committed.

So thinking about this, this would also affect objectClass referral if no aci was there to allow to read this due to the way we transform. Now the symptoms you describe are likely due to:

-        *candidates = onelevel_candidates(pb, be, base, e, filter, managedsait,
-                                          lookup_returned_allidsp, &err);
+        /* modify the filter to be: (&(parentid=idofbase)(|(originalfilter)(objectclass=referral))) */
+        filter = create_onelevel_filter(filter, e, managedsait);
+        /* Now optimise the filter for use */
+        slapi_filter_optimise(filter, filter_optimise);
+
+        *candidates = onelevel_candidates(pb, be, base, filter, lookup_returned_allidsp, &err);
+        /* Give the optimised filter back to search filter for free */
+        slapi_pblock_set(pb, SLAPI_SEARCH_FILTER, filter);
         break;
     case LDAP_SCOPE_SUBTREE:
-        *candidates = subtree_candidates(pb, be, base, e, filter, managedsait,
-                                         lookup_returned_allidsp, &err);
+        /* make (|(originalfilter)(objectclass=referral)) */
+        filter = create_subtree_filter(filter, managedsait);
+        /* Now optimise the filter for use */
+        slapi_filter_optimise(filter, filter_optimise);
+
+        *candidates = subtree_candidates(pb, be, base, e, filter, lookup_returned_allidsp, &err);
+        /* Give the optimised filter back to search filter for free */
+        slapi_pblock_set(pb, SLAPI_SEARCH_FILTER, filter);

The filter as it was executed (optimised) is returned to the pb to allow it to be freed later. However it appears in the original that the onelevel and referral filters are not returned to the pb.

This would (as you mention) cause the filter from the pb in the aci test to then have the extra components as you describe that are not allowed by the aci.

I think there are a few ways to handle thing possibly.

  • clone the filter as part of create_subtree/onelevel/optimise, leaving the original untouched, and free the optimised version.
  • add exemptions for objectClass=referral and parentid in the aci check so that they can always operate on these filters
  • Have the optimised filter returned to the PB in a different section IE filter_as_executed or similar, so that it can be audited / compared to the original filter and freed later.

I'm going to think about this a bit, but suggestions on these options or further ways to resolve this would be good to know. I think there are good/bad elements to each option.

So after some thinking, I think we should store the filter as optimised/executed in the pb, so that we can log "what was intended" by the user and "what was executed" by the server. That way we can still do the aci check on the "user intended" filter.

Thoughts @lkrispen?

So after some thinking, I think we should store the filter as optimised/executed in the pb, so that we can log "what was intended" by the user and "what was executed" by the server. That way we can still do the aci check on the "user intended" filter.
Thoughts @lkrispen?

you mean to store both filters and use them for different purposes ? That's ok for me
Edited by lkrispen

Yep, that's exactly my intent. Since it's okay by you, I'll work on this, and also provide the load testing results soon. Thank you for your help with this, it's much appreciated.

and the problems with #48275 need to be addressed.

Here is a simple scenario to show what is going wrong:

assume you have user with access to "uid" but no access to "employeenumber", this user is doing a search with filter: "(|(uid=user.1)(employeenumber=3))"

current master returns the entries matching the uid part, with your patch no entry is returned.
But doing separate searches for "uid=user.1" returns 2 entries (data from the testcase in the ticket), and for "employeenumber=3" returns no entry.

An OR filter always can be split into multiple searches with the individual OR components and retrieve the entries matching. There is no reason to not return them in the OR search - and this is the current behaviour and should not be changed

rebased onto 0355f62a9b8210df6210a97bf085afa69296f4fa

@lkrispen I have included both 48275 and 49617. I also ensured to add your example of (|(allowed=...)(denied=...)) into the test cases and have confirmed it passes. Finally, I have asserted that the new additions to the pb are freed so there should be no leaks or bad behaviour here. There are still some patch cleanups for me to do to be sure, and I need to provide load test numbers for you. Thanks for your huge, huge amount of patience with me on this issue!

note to self: test with vlv

VLV has a memory leak now :( working to resolve this.

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/3311

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi
Metadata
None
No Tags
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.