Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Nightly test failure in IPA server installation #5332

Closed
flo-renaud opened this issue Jun 5, 2022 · 18 comments · Fixed by #5342
Closed

Nightly test failure in IPA server installation #5332

flo-renaud opened this issue Jun 5, 2022 · 18 comments · Fixed by #5342
Labels
needs triage The issue will be triaged during scrum

Comments

@flo-renaud
Copy link

The IPA tests using the nightly build of 389-ds (from the copr repo @389ds/389-ds-base-nightly) are failing during IPA server installation, in the discovery phase of ipa-client-install. See for instance PR #1764 with the folllowing test: automember (Report, logs):

...
Configuring client side components
Using existing certificate '/etc/ipa/ca.crt'.
Skip master.ipa.test: not an IPA server
Failed to verify that master.ipa.test is an IPA Server.
This may mean that the remote server is not up or is not reachable due to network or firewall settings.
Please make sure the following ports are opened in the firewall settings:
     TCP: 80, 88, 389
     UDP: 88 (at least one of TCP/UDP ports 88 has to be open)
Also note that following ports are necessary for ipa-client working properly after enrollment:
     TCP: 464
     UDP: 464, 123 (if NTP enabled)
The ipa-client-install command failed. See /var/log/ipaclient-install.log for more information
This program will set up IPA client.
Version 4.10.0.dev

Configuration of client side components failed!
The ipa-server-install command failed. See /var/log/ipaserver-install.log for more information

Investigations

The code is doing the equivalent of the following LDAP command to check if the server is an IPA server:

LDAPTLS_CACERT=/etc/ipa/ca.crt ldapsearch -x -ZZ -b dc=ipa,dc=test -s base  "(info=IPA*)"

and the command doesn't find any entry. Note that without the -s base option, the entry is properly returned:

# LDAPTLS_CACERT=/etc/ipa/ca.crt ldapsearch -x -ZZ -b dc=ipa,dc=test  "(info=IPA*)"
# extended LDIF
#
# LDAPv3
# base <dc=ipa,dc=test> with scope subtree
# filter: (info=IPA*)
# requesting: ALL
#

# ipa.test
dn: dc=ipa,dc=test
objectClass: top
objectClass: domain
objectClass: pilotObject
objectClass: domainRelatedObject
objectClass: nisDomainObject
dc: ipa
info: IPA V2.0
associatedDomain: ipa.test
nisDomain: ipa.test

# search result
search: 3
result: 0 Success

# numResponses: 2
# numEntries: 1

Installed packages: 389-ds-base-2.2.1-202206031947git9763e161e.fc36.x86_64

Companion issue logged against IPA: https://pagure.io/freeipa/issue/9170

@flo-renaud flo-renaud added the needs triage The issue will be triaged during scrum label Jun 5, 2022
@abbra
Copy link

abbra commented Jun 7, 2022

FYI, we also discuss this regression in Fedora: https://bodhi.fedoraproject.org/updates/FEDORA-2022-e9c10b569e
What fails (and what actually breaks IPA deployments) is LDAP search with a base scope against $SUFFIX. Even after I added ACI to allow anonymous users to access info attribute for search/read/compare, base-level search still does not succeed. You can find logs in the Fedora bodhi discussion.

This is definitely a huge regression for us as it breaks all client code out there in all distributions. A mere check for whether this is IPA server is not working anymore.

@Firstyear
Copy link
Contributor

@abbra Have you got the latest updates from #5315 and all the preceding commits.

@flo-renaud
Copy link
Author

@Firstyear
the issue was reproduced with 389-ds-base-2.2.1-202206031947git9763e161e.fc36.x86_64 = master branch with commit 9763e161, which contains the following:

9763e161e (Bump version to 2.2.1, 2022-06-03)
419461df8 (Issue 5323 - BUG - Fix issue in mdb tests with monitor (#5326), 2022-06-03)
40563667e (Issue 5170 - BUG - incorrect behaviour of filter test (#5315), 2022-06-03)
6eecf3bb1 (Issue 5324 - plugin acceptance test needs hardening, 2022-06-01)
987821a4e (Issue 5319 - dsctl_tls_test.py fails with openssl-3.x, 2022-05-30)
a393afe5b (Issue 5323 - BUG - migrating database for monitoring interface lead to crash (#5321), 2022-06-01)
83b3fe968 (Issue 5304: Need a compatibility option about sub suffix handling (#5310), 2022-05-31)
51dcc37a0 (Issue 5313 - dbgen test uses deprecated -h HOST and -p PORT options for ldapmodify, 2022-05-27)
23e01a7d7 (Issue 5311 - Missing Requires for acl in the spec file, 2022-05-27)
ab5e4b302 (Issue 5305 - OpenLDAP version autodetection doesn't work, 2022-05-23)
89033bea4 (Issue 5307 - VERSION_PREREL is not set correctly in CI builds, 2022-05-24)
cfab2c1be (Issue 5302 - Release tarballs don't contain cockpit webapp, 2022-05-23)
df1abddb5 (Issue 5170 - RFE - improve filter logging to assist debugging (#5301), 2022-05-19)
53d0e1701 (Issue 5299 - jemalloc 5.3 released, 2022-05-17)
01857c348 (Issue 5175 - Remove stale zlib-devel dependency declaration (#5173), 2022-05-16)
39d843cc0 (Issue 5294 - Report Portal 5 is not processing test results XML file, 2022-05-12)
682bbfb5c (Issue 5170 - BUG - ldapsubentries were incorrectly returned (#5285), 2022-05-14)
b15004051 (Issue 5291 - Harden ReplicationManager.wait_for_replication (#5292), 2022-05-13)
641221788 (Issue 379 - RFE - Compress rotated logs (fix linker), 2022-05-12)
7b52d40b0 (Issue 379 - RFE - Compress rotated logs, 2022-05-06)
18a5f7e21 (Issue 5281 - HIGH - basic test does not run, 2022-05-05)
b169df298 (Issue 5284 - Replication broken after password change (#5286), 2022-05-10)
4cfefd799 (Issue 5279 - dscontainer: TypeError: unsupported operand type(s) for /: 'str' and 'int', 2022-05-04)
90d847426 (Issue 5170 - RFE - Filter optimiser (#5171), 2022-05-05)
...

@Firstyear
Copy link
Contributor

Okay. That means there are new and improved filter logs. We need those to diagnose this.

@Firstyear
Copy link
Contributor

The second thing to raise here is that @mreynolds389 confirmed that these patches passed with freeipa, so how was this missed in ipa's testing, and now causing "an issue via bodhi".

@abbra
Copy link

abbra commented Jun 7, 2022

@Firstyear I don't believe @mreynolds389 tested the same thing against IPA. It is clearly breaking our nightly tests when using 389-ds nightly build. I think what @mreynolds389 talks about is https://pagure.io/freeipa/issue/9153 (389-ds issue #5289), which is different from this use case.

@flo-renaud
Copy link
Author

@Firstyear the tests were executed using this build: https://copr.fedorainfracloud.org/coprs/g/389ds/389-ds-base-nightly/build/4460276/
I assume the branch containing this commit cfab2c1 was a private branch that did not contain exactly the same patches as the master branch.

@abbra
Copy link

abbra commented Jun 7, 2022

@Firstyear I have provided logs to Mark at the bodhi update. Here is the same log pasted, this is a diff for ldapsearch -b base "info=IPA*" request, with ACI and filter logs enabled:

+[06/Jun/2022:13:13:28.953135887 +0000] - DEBUG - slapi_str2filter - "(|(objectclass=*)(objectclass=ldapsubentry))"
+[06/Jun/2022:13:13:28.964415227 +0000] - DEBUG - slapi_str2filter - OR
+[06/Jun/2022:13:13:28.967611694 +0000] - DEBUG - str2list - "(objectclass=*)(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:28.971022125 +0000] - DEBUG - slapi_str2filter - "(objectclass=*)"
+[06/Jun/2022:13:13:28.973902870 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:28.976724299 +0000] - DEBUG - str2simple - "objectclass=*"
+[06/Jun/2022:13:13:28.979573464 +0000] - DEBUG - slapi_str2filter - "(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:28.984881770 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:28.989922981 +0000] - DEBUG - str2simple - "objectclass=ldapsubentry"
+[06/Jun/2022:13:13:28.995363961 +0000] - DEBUG - ldbm_back_search - Applying Filter Test
+[06/Jun/2022:13:13:29.000039166 +0000] - DEBUG - slapi_filter_dup - type 0xA1
+[06/Jun/2022:13:13:29.005329015 +0000] - DEBUG - slapi_filter_dup - type 0x87
+[06/Jun/2022:13:13:29.009906800 +0000] - DEBUG - slapi_filter_dup - type 0xA3
+[06/Jun/2022:13:13:29.014971165 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test to cn=anonymous-limits,cn=etc,dc=ipa,dc=test
+[06/Jun/2022:13:13:29.020002971 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.025043116 +0000] - DEBUG - slapi_vattr_filter_test_ext_internal - acl result for cn=anonymous-limits,cn=etc,dc=ipa,dc=test objectClass = 0
+[06/Jun/2022:13:13:29.030577011 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.036205982 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test intermediate value 0 
+[06/Jun/2022:13:13:29.042930231 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.048183383 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.054006213 +0000] - DEBUG - ldbm_back_next_search_entry - filter test value 0 cn=anonymous-limits,cn=etc,dc=ipa,dc=test 
+[06/Jun/2022:13:13:29.059548027 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.065136827 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.070585395 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.076324701 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.082238416 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.088119587 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.113485741 +0000] - DEBUG - slapi_str2filter - "(|(objectclass=*)(objectclass=ldapsubentry))"
+[06/Jun/2022:13:13:29.117694813 +0000] - DEBUG - slapi_str2filter - OR
+[06/Jun/2022:13:13:29.121729501 +0000] - DEBUG - str2list - "(objectclass=*)(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:29.125811545 +0000] - DEBUG - slapi_str2filter - "(objectclass=*)"
+[06/Jun/2022:13:13:29.133204706 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:29.137123220 +0000] - DEBUG - str2simple - "objectclass=*"
+[06/Jun/2022:13:13:29.140973176 +0000] - DEBUG - slapi_str2filter - "(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:29.144958312 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:29.148766260 +0000] - DEBUG - str2simple - "objectclass=ldapsubentry"
+[06/Jun/2022:13:13:29.152530122 +0000] - DEBUG - ldbm_back_search - Applying Filter Test
+[06/Jun/2022:13:13:29.156508675 +0000] - DEBUG - slapi_filter_dup - type 0xA1
+[06/Jun/2022:13:13:29.160444626 +0000] - DEBUG - slapi_filter_dup - type 0x87
+[06/Jun/2022:13:13:29.164325629 +0000] - DEBUG - slapi_filter_dup - type 0xA3
+[06/Jun/2022:13:13:29.167929892 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test to cn=anonymous-limits,cn=etc,dc=ipa,dc=test
+[06/Jun/2022:13:13:29.171834573 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.175602057 +0000] - DEBUG - slapi_vattr_filter_test_ext_internal - acl result for cn=anonymous-limits,cn=etc,dc=ipa,dc=test objectClass = 0
+[06/Jun/2022:13:13:29.179339397 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.183060721 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test intermediate value 0 
+[06/Jun/2022:13:13:29.187074021 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.192102791 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.197102760 +0000] - DEBUG - ldbm_back_next_search_entry - filter test value 0 cn=anonymous-limits,cn=etc,dc=ipa,dc=test 
+[06/Jun/2022:13:13:29.202198549 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.210677830 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.216120160 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.221971155 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.227671591 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.232923786 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.238736531 +0000] - DEBUG - slapi_str2filter - "(|(objectclass=*)(objectclass=ldapsubentry))"
+[06/Jun/2022:13:13:29.243687920 +0000] - DEBUG - slapi_str2filter - OR
+[06/Jun/2022:13:13:29.248916909 +0000] - DEBUG - str2list - "(objectclass=*)(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:29.255138851 +0000] - DEBUG - slapi_str2filter - "(objectclass=*)"
+[06/Jun/2022:13:13:29.259687640 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:29.265004598 +0000] - DEBUG - str2simple - "objectclass=*"
+[06/Jun/2022:13:13:29.269901968 +0000] - DEBUG - slapi_str2filter - "(objectclass=ldapsubentry)"
+[06/Jun/2022:13:13:29.275169955 +0000] - DEBUG - slapi_str2filter - simple
+[06/Jun/2022:13:13:29.280567125 +0000] - DEBUG - str2simple - "objectclass=ldapsubentry"
+[06/Jun/2022:13:13:29.286331111 +0000] - DEBUG - ldbm_back_search - Applying Filter Test
+[06/Jun/2022:13:13:29.292582662 +0000] - DEBUG - slapi_filter_dup - type 0xA1
+[06/Jun/2022:13:13:29.298275139 +0000] - DEBUG - slapi_filter_dup - type 0x87
+[06/Jun/2022:13:13:29.303842130 +0000] - DEBUG - slapi_filter_dup - type 0xA3
+[06/Jun/2022:13:13:29.309479481 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test to cn=anonymous-limits,cn=etc,dc=ipa,dc=test
+[06/Jun/2022:13:13:29.315283617 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.320560479 +0000] - DEBUG - slapi_vattr_filter_test_ext_internal - acl result for cn=anonymous-limits,cn=etc,dc=ipa,dc=test objectClass = 0
+[06/Jun/2022:13:13:29.326328688 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.331496077 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test intermediate value 0 
+[06/Jun/2022:13:13:29.337173488 +0000] - DEBUG - vattr_test_filter_list_or - =>
+[06/Jun/2022:13:13:29.342547912 +0000] - DEBUG - vattr_test_filter_list_or - <= 0
+[06/Jun/2022:13:13:29.348223515 +0000] - DEBUG - ldbm_back_next_search_entry - filter test value 0 cn=anonymous-limits,cn=etc,dc=ipa,dc=test 
+[06/Jun/2022:13:13:29.353798381 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.358852392 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.364218475 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.369373813 +0000] - DEBUG - slapi_filter_free - type 0xA1
+[06/Jun/2022:13:13:29.375166907 +0000] - DEBUG - slapi_filter_free - type 0x87
+[06/Jun/2022:13:13:29.380687065 +0000] - DEBUG - slapi_filter_free - type 0xA3
+[06/Jun/2022:13:13:29.387214128 +0000] - DEBUG - get_filter_internal - ==>
+[06/Jun/2022:13:13:29.392728770 +0000] - DEBUG - get_filter_internal - SUBSTRINGS
+[06/Jun/2022:13:13:29.397932414 +0000] - DEBUG - get_substring_filter - =>
+[06/Jun/2022:13:13:29.403027948 +0000] - DEBUG - get_substring_filter - INITIAL
+[06/Jun/2022:13:13:29.408368569 +0000] - DEBUG - get_substring_filter - <=
+[06/Jun/2022:13:13:29.412867418 +0000] - DEBUG - get_filter_internal - <= 0
+[06/Jun/2022:13:13:29.417219999 +0000] - DEBUG - ldbm_back_search - Applying Filter Test
+[06/Jun/2022:13:13:29.421480244 +0000] - DEBUG - slapi_filter_dup - type 0xA4
+[06/Jun/2022:13:13:29.426477394 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test to dc=ipa,dc=test
+[06/Jun/2022:13:13:29.429986353 +0000] - DEBUG - NSACLPlugin - aclanom_match_profile - conn=146 op=1: Allow access on entry(dc=ipa,dc=test).attr(info) to anonymous: acidn="dc=ipa,dc=test"
+[06/Jun/2022:13:13:29.433268093 +0000] - DEBUG - NSACLPlugin - print_access_control_summary - conn=146 op=1 (main): Allow search on entry(dc=ipa,dc=test).attr(info) to anonymous: allow anyone aci matched anon user
+[06/Jun/2022:13:13:29.436613977 +0000] - DEBUG - slapi_vattr_filter_test_ext_internal - acl result for dc=ipa,dc=test info = 0
+[06/Jun/2022:13:13:29.440458560 +0000] - DEBUG - test_substring_filter - <=
+[06/Jun/2022:13:13:29.442779432 +0000] - DEBUG - plugin_call_syntax_filter_sub_sv - =>
+[06/Jun/2022:13:13:29.445428010 +0000] - DEBUG - plugin_call_syntax_filter_sub_sv - <= -1
+[06/Jun/2022:13:13:29.449678520 +0000] - DEBUG - test_substring_filter - <= -1
+[06/Jun/2022:13:13:29.452055005 +0000] - DEBUG - ldbm_back_next_search_entry - Applying filter test intermediate value -1 
+[06/Jun/2022:13:13:29.454218717 +0000] - DEBUG - ldbm_back_next_search_entry - filter test value -1 dc=ipa,dc=test 
+[06/Jun/2022:13:13:29.456773877 +0000] - DEBUG - slapi_filter_free - type 0xA4
+[06/Jun/2022:13:13:29.460149843 +0000] - DEBUG - slapi_filter_free - type 0xA4

@mreynolds389
Copy link
Contributor

I am looking into this to find a simple reproducer. Now IPA does have an aci that already allowed "info":

aci: (targetfilter="(objectclass=domain)")(targetattr="objectclass || dc || info
|| nisDomain || associatedDomain")(version 3.0; acl "Anonymous read access
to DIT root"; allow(read, search, compare) userdn = "ldap:///anyone";)

ACI code shows that access was granted to both subtree/base searches, but "test_fitler_access" is returning -1 for the base search which is blocking the entry from being returned. So it is ACI related, but I'm not sure how yet.

@mreynolds389
Copy link
Contributor

mreynolds389 commented Jun 7, 2022

I still can not reproduce the issue outside of IPA but this is an interesting observation. An exact filter works with base search, but a substring search does not:

# ldapsearch -xLLL -b "dc=ipa,dc=test" -s base  "(info=IPA*)"
# ldapsearch -xLLL -b "dc=ipa,dc=test" -s base  "(info=IPA V2.0)"
dn: dc=ipa,dc=test
objectClass: top
objectClass: domain
objectClass: pilotObject
objectClass: domainRelatedObject
objectClass: nisDomainObject
dc: ipa
info: IPA V2.0
nisDomain: ipa.test
associatedDomain: ipa.test

Still investigating...

@mreynolds389
Copy link
Contributor

mreynolds389 commented Jun 7, 2022

Update:

The problem is that with base search we are not normalizing the filter in the pblock. We normalize the filter in the search result set, but not in the pblock, and the pblock filter is what is used in ldbm_back_next_search_entry(). Instead we use the "intended filter" which was not normalized.

To reproduce:

On the root node entry set "info" which has a CIS syntax (so case should not matter, but as you'll see it will):

dn: dc=example,dc=com
objectClass: top
objectClass: domain
objectClass: extensibleobject
dc: example
info: IPAv2.0
aci: (targetfilter="(objectclass=domain)")(targetattr="objectclass || dc ||  info")(version 3.0; acl "Anonymous read access to DIT root "; allow(read, search, compare) userdn = "ldap:///anyone";)

Then we try this search which should work but it does not:

# ldapsearch -xLLL -b dc=example,dc=com -s base "(info=IPA*)"

Change the case of the filter attribute value to lowercase and it works:

# ldapsearch -xLLL -b dc=example,dc=com -s base "(info=ipa*)"
dn: dc=example,dc=com
objectClass: top
objectClass: domain
objectClass: extensibleobject
dc: example
info: IPAv2.0

The second search works because in the code we have marked the filter as normalized, but in fact it is not. So by using the lower case value it does find the entry because we did the normalization ourselves. So filter normalization is not happening correctly on base searches.

@Firstyear
Copy link
Contributor

The problem is that with base search we are not normalizing the filter in the pblock. We normalize the filter in the search result set, but not in the pblock, and the pblock filter is what is used in ldbm_back_next_search_entry(). Instead we use the "intended filter" which was not normalized.

When is the normalising step occuring? Can you point me to the line of code? Or will you just do a PR? (I can't really look today :( )

@mreynolds389
Copy link
Contributor

mreynolds389 commented Jun 8, 2022

@Firstyear

So the problems happens in ldbm_search.c:1760

                    slapi_log_err(SLAPI_LOG_FILTER, "ldbm_back_next_search_entry",
                                  "Applying filter test to %s\n", slapi_entry_get_dn_const(e->ep_entry));
                    filter_test = slapi_vattr_filter_test(pb, e->ep_entry, filter_intent, ACL_CHECK_FLAG);
                    slapi_log_err(SLAPI_LOG_FILTER, "ldbm_back_next_search_entry",
                                  "Applying filter test intermediate value %d \n", filter_test);

With substring searches the "filter_intent" has been normalized, but for base searches it has not (but the "filter" variable in this function is normalized).

at line 1469 we have:

    if (sr->sr_norm_filter) {
        int val = 1;
        slapi_pblock_set(pb, SLAPI_PLUGIN_SYNTAX_FILTER_NORMALIZED, &val);
        filter = sr->sr_norm_filter;
    }

So above we flag the filter as normalized in the pblock and the local variable "filter" is set to the normalized filter, but we use "filter_intent" when calling "slapi_vattr_filter_test()" which in the base search case is not normalized. Notice that sf_initial's case "IPA" vs "ipa":

(gdb) p *filter
$28 = {f_flags = 25, f_choice = 164, f_hash = 0, assigned_decoder = 0x0, f_un = {f_un_type = 0x7f79a5403030 "info", f_un_ava = {ava_type = 0x7f79a5403030 "info", 
      ava_value = {bv_len = 140160440217640, bv_val = 0x0}, ava_private = 0x0}, f_un_complex = 0x7f79a5403030, f_un_sub = {sf_type = 0x7f79a5403030 "info", 
      sf_initial = 0x7f79a5403028 "ipa", sf_any = 0x0, sf_final = 0x0, sf_private = 0x7f79a540f140}, f_un_extended = {mrf_type = 0x7f79a5403030 "info", mrf_value = {
        bv_len = 140160440217640, bv_val = 0x0}, mrf_oid = 0x0, mrf_dnAttrs = 64 '@', mrf_match = 0x0, mrf_index = 0x0, mrf_reusable = 0, mrf_reset = 0x0, 
      mrf_object = 0x0, mrf_destroy = 0x0}}, f_next = 0x0}

(gdb) p *filter_intent
$29 = {f_flags = 1, f_choice = 164, f_hash = 0, assigned_decoder = 0x0, f_un = {f_un_type = 0x7f79a5403018 "info", f_un_ava = {ava_type = 0x7f79a5403018 "info", 
      ava_value = {bv_len = 140160440217616, bv_val = 0x0}, ava_private = 0x0}, f_un_complex = 0x7f79a5403018, f_un_sub = {sf_type = 0x7f79a5403018 "info", 
      sf_initial = 0x7f79a5403010 "IPA", sf_any = 0x0, sf_final = 0x0, sf_private = 0x0}, f_un_extended = {mrf_type = 0x7f79a5403018 "info", mrf_value = {
        bv_len = 140160440217616, bv_val = 0x0}, mrf_oid = 0x0, mrf_dnAttrs = 0 '\000', mrf_match = 0x0, mrf_index = 0x0, mrf_reusable = 0, mrf_reset = 0x0, 
      mrf_object = 0x0, mrf_destroy = 0x0}}, f_next = 0x0}

I "think" the issue might be that for substring searches we modify the filter to include objectclass=referral, and I think that's were we normalize the filter in the pblock (not sure on that though). I'll try to continue to look into this today, but I will be out most of Thursday and Friday...

@mreynolds389
Copy link
Contributor

Here is a hack fix :-)

diff --git a/ldap/servers/slapd/back-ldbm/ldbm_search.c b/ldap/servers/slapd/back-ldbm/ldbm_search.c
index 3b032597b..f26553a4b 100644
--- a/ldap/servers/slapd/back-ldbm/ldbm_search.c
+++ b/ldap/servers/slapd/back-ldbm/ldbm_search.c
@@ -1470,6 +1470,9 @@ ldbm_back_next_search_entry(Slapi_PBlock *pb)
         int val = 1;
         slapi_pblock_set(pb, SLAPI_PLUGIN_SYNTAX_FILTER_NORMALIZED, &val);
         filter = sr->sr_norm_filter;
+        if (scope == LDAP_SCOPE_BASE) {
+            filter_intent = filter;
+        }
     }
 
     if (op_is_pagedresults(op)) {

@progier389
Copy link
Contributor

I would rather fix in in build_candidate_list in the LDAP_SCOPE_BASE case ...
IMHO the following lines are missing
slapi_pblock_set(pb, SLAPI_SEARCH_FILTER, filter);
slapi_pblock_set(pb, SLAPI_SEARCH_FILTER_INTENDED, filter);

@mreynolds389
Copy link
Contributor

I would rather fix in in build_candidate_list in the LDAP_SCOPE_BASE case ... IMHO the following lines are missing slapi_pblock_set(pb, SLAPI_SEARCH_FILTER, filter); slapi_pblock_set(pb, SLAPI_SEARCH_FILTER_INTENDED, filter);

I tried it but it doesn't help. Based on your recommendation I revised my "fix" which is a little cleaner, but it still feels like a hack

diff --git a/ldap/servers/slapd/back-ldbm/ldbm_search.c b/ldap/servers/slapd/back-ldbm/ldbm_search.c
index 3b032597b..9cc986700 100644
--- a/ldap/servers/slapd/back-ldbm/ldbm_search.c
+++ b/ldap/servers/slapd/back-ldbm/ldbm_search.c
@@ -1002,6 +1002,7 @@ build_candidate_list(Slapi_PBlock *pb, backend *be, struct backentry *e, const c
     switch (scope) {
     case LDAP_SCOPE_BASE:
         *candidates = base_candidates(pb, e);
+        slapi_filter_normalize(filter, PR_TRUE /* normalize values too */);
         break;
 
     case LDAP_SCOPE_ONELEVEL:

Firstyear added a commit to Firstyear/389-ds-base that referenced this issue Jun 10, 2022
Bug Description: Due to a mistake in the optimiser rework
the filter as intended was not normalised, causing some searches
to fail

Fix Description: Always normalise both filters.

fixes: 389ds#5332

Author: William Brown <william@blackhats.net.au>

Review by: ???
@Firstyear
Copy link
Contributor

I think there is a better fix:

#5341

I also want a test case for this, but I have another bug from a SUSE customer to deal with RN. :(

@mreynolds389
Copy link
Contributor

Testcase:

diff --git a/dirsrvtests/tests/suites/filter/filter_test_aci_with_optimiser.py b/dirsrvtests/tests/suites/filter/filter_test_aci_with_optimiser.py
index fdf044a2f..f78a319b1 100644
--- a/dirsrvtests/tests/suites/filter/filter_test_aci_with_optimiser.py
+++ b/dirsrvtests/tests/suites/filter/filter_test_aci_with_optimiser.py
@@ -83,6 +83,35 @@ def test_filter_access(topo):
         assert len(entries) == 0
 
 
+def test_base_search_with_substring_filter(topo):
+    """Test that filter normalization works correctly with base search using
+    substring filter
+
+    :id: 8391ffc4-5158-4141-9312-0f47ae56f1ed
+    :setup: Standalone Instance
+    :steps:
+        1. Add ACI allowing search on "description"
+        2. Add "description" to root suffix and make it upper case to test normalization
+        3. Do base search with substring filter
+    :expectedresults:
+        1. Success
+        2. Success
+        3. Success
+    """
+
+    # Add aci
+    ACI_TEXT = ('(targetattr="description")(version 3.0; acl "Anonymous read access"; allow' +
+                '(read, search, compare) userdn = "ldap:///anyone";)')
+    domain = Domain(topo.standalone, DEFAULT_SUFFIX)
+    domain.replace('aci', ACI_TEXT)
+    domain.replace('description', 'ACCESS')  # case is important
+
+    # open anonymous connection and do base search with substring filter
+    conn = Anonymous(topo.standalone).bind()
+    entries = conn.search_s(DEFAULT_SUFFIX, ldap.SCOPE_BASE, "description=ACCE*")
+    assert len(entries) == 1
+
+
 if __name__ == '__main__':
     # Run isolated
     # -s for DEBUG mode

mreynolds389 pushed a commit to mreynolds389/389-ds-base that referenced this issue Jun 14, 2022
Bug Description: Due to a mistake in the optimiser rework
the filter as intended was not normalised, causing some searches
to fail

Fix Description: Always normalise both filters.

fixes: 389ds#5332

Author: William Brown <william@blackhats.net.au>

Review by: mreynolds (Thanks!)

Signed-off-by: Mark Reynolds <mreynolds@redhat.com>
mreynolds389 pushed a commit that referenced this issue Jun 14, 2022
Bug Description: Due to a mistake in the optimiser rework
the filter as intended was not normalised, causing some searches
to fail

Fix Description: Always normalise both filters.

fixes: #5332

Author: William Brown <william@blackhats.net.au>

Review by: mreynolds (Thanks!)

Signed-off-by: Mark Reynolds <mreynolds@redhat.com>
mreynolds389 pushed a commit that referenced this issue Jun 14, 2022
Bug Description: Due to a mistake in the optimiser rework
the filter as intended was not normalised, causing some searches
to fail

Fix Description: Always normalise both filters.

fixes: #5332

Author: William Brown <william@blackhats.net.au>

Review by: mreynolds (Thanks!)

Signed-off-by: Mark Reynolds <mreynolds@redhat.com>
mreynolds389 pushed a commit that referenced this issue Jun 14, 2022
Bug Description: Due to a mistake in the optimiser rework
the filter as intended was not normalised, causing some searches
to fail

Fix Description: Always normalise both filters.

fixes: #5332

Author: William Brown <william@blackhats.net.au>

Review by: mreynolds (Thanks!)

Signed-off-by: Mark Reynolds <mreynolds@redhat.com>
Ma27 added a commit to Ma27/nixpkgs that referenced this issue Feb 27, 2024
Doesn't build with glibc 2.39. There's a potential fix documented in
389ds/389-ds-base#5332, but the package is too
old for the patch to apply, so I'll mark it as broken for now and leave
it to the maintainer to update & fix.
Ma27 added a commit to Ma27/nixpkgs that referenced this issue Mar 2, 2024
Doesn't build with glibc 2.39. There's a potential fix documented in
389ds/389-ds-base#5332, but the package is too
old for the patch to apply, so I'll mark it as broken for now and leave
it to the maintainer to update & fix.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
needs triage The issue will be triaged during scrum
Projects
None yet
5 participants