Regression related to sync_repl in ipa nightly tests #5289

flo-renaud · 2022-05-09T15:12:58Z

Issue Description
FreeIPA nightly tests detected a regression introduced with commit 90d8474. See for instance the PR #1695 with the test 389ds-fedora/test_backup_and_restore_TestBackupAndRestore (logs, report).

Package Version and Platform:

Platform: Fedora 35
Package and version: 389-ds-base-2.2.0-202205031357git0ca6689f2.fc35.x86_64

Steps to Reproduce
Steps to reproduce the behavior:
On a host with hostname = server.ipa.test
1, install freeipa-server-dns: dnf install -y freeipa-server-dns
2. Enable 389ds copr repo: dnf copr enable @389ds/389-ds-base-nightly
3. update 389ds to the faulty version: dnf update 389-ds-base-2.2.0-202205050142git90d847426.fc35
4. install ipa server: ipa-server-install --domain ipa.test --realm IPA.TEST --setup-dns --auto-forwarders --no-dnssec-validation -a Secret123 -p Secret123 -U
5. query the DNS for the server name: host server.ipa.test localhost
The query fails:

# host server.ipa.test localhost
Using domain server:
Name: localhost
Address: ::1#53
Aliases: 

Host server.ipa.test not found: 3(NXDOMAIN)

Expected results
The DNS server should answer with the server IP adress:

Using domain server:
Name: localhost
Address: ::1#53
Aliases: 

server.ipa.test has address 10.0.138.213

The DNS server logs show issues related to sync_repl: /var/named/data/database.log

The DNS server relies heavily on sync_repl as it performs queries to find the DNS-related objects in the LDAP database. If sync_repl fails, the DNS server cannot load/update the entries.

Companion issue logged against freeipa: https://pagure.io/freeipa/issue/9153

The text was updated successfully, but these errors were encountered:

progier389 · 2022-05-09T16:21:17Z

FYI: We also have a regression in 389ds test related to this commit, @Firstyear is working on it through
#5285

flo-renaud · 2022-05-15T11:47:31Z

The PR #5285 fixed a few issues but not all of them. We still have the problem with sync_repl.

mreynolds389 · 2022-05-15T19:56:01Z

@flo-renaud Just trying to understand what the "sync-repl" failure actually is.

Is this the search filter that fails:

'(|(objectClass=idnsConfigObject)(&(objectClass=idnsServerConfigObject)(idnsServerId=master.ipa.test))(|(objectClass=idnsZone)(objectClass=idnsForwardZone)(objectClass=idnsRecord)))'

And do you have an example of the entry that should match this filter?

flo-renaud · 2022-05-16T07:23:24Z

The first filter used is the following (with LDAP_SYNC_REFRESH_ONLY):
SRCH base="cn=dns,dc=ipa,dc=test" scope=2 filter="(|(objectClass=idnsConfigObject)(&(objectClass=idnsServerConfigObject)(idnsServerId=server.ipa.test)))" attrs=ALL
and should return 2 entries, the top-level one and the server entry:

dn: cn=dns,dc=ipa,dc=test
objectClass: idnsConfigObject
objectClass: nsContainer
objectClass: ipaConfigObject
objectClass: ipaDNSContainer
objectClass: top
cn: dns
ipaConfigString: DNSVersion 1
ipaDNSVersion: 2

dn: idnsserverid=server.ipa.test,cn=servers,cn=dns,dc=ipa,dc=test
idnsServerId: server.ipa.test
idnsSOAmName: server.ipa.test.
objectClass: top
objectClass: idnsServerConfigObject
idnsForwarders: 10.2.32.1
idnsForwardPolicy: only

Then subsequent call is using the filter you provided (with LDAP_SYNC_REFRESH_AND_PERSIST):
SRCH base="cn=dns,dc=ipa,dc=test" scope=2 filter="(|(objectClass=idnsConfigObject)(&(objectClass=idnsServerConfigObject)(idnsServerId=server.ipa.test))(|(objectClass=idnsZone)(objectClass=idnsForwardZone)(objectClass=idnsRecord)))" attrs=ALL
For a simple deployment with one server, and only one DNS zone, I get the following entries:

dn: cn=dns,dc=ipa,dc=test
objectClass: idnsConfigObject
objectClass: nsContainer
objectClass: ipaConfigObject
objectClass: ipaDNSContainer
objectClass: top
cn: dns
ipaConfigString: DNSVersion 1
ipaDNSVersion: 2

dn: idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsSOArName: hostmaster.ipa.test.
idnsSOArefresh: 3600
idnsSOAretry: 900
idnsSOAexpire: 1209600
idnsSOAminimum: 3600
idnsName: ipa.test.
idnsSOAserial: 1652683744
idnsSOAmName: server.ipa.test.
idnsUpdatePolicy: grant IPA.TEST krb5-self * A; grant IPA.TEST krb5-self * AAAA; grant IPA.TEST krb5-self * SSHFP;
idnsAllowDynUpdate: TRUE
idnsAllowQuery: any;
idnsAllowTransfer: none;
objectClass: top
objectClass: idnsrecord
objectClass: idnszone
idnsZoneActive: TRUE
nSRecord: server.ipa.test.

dn: idnsname=_kerberos,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kerberos
objectClass: top
objectClass: idnsrecord
tXTRecord: "IPA.TEST"
URIRecord: 0 100 "krb5srv:m:tcp:server.ipa.test."
URIRecord: 0 100 "krb5srv:m:udp:server.ipa.test."

dn: idnsname=server,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: server
aRecord: 10.0.138.246
objectClass: top
objectClass: idnsrecord
sSHFPRecord: 1 1 33E15FDBE27D088E737DDAAD4C2E9F7CCEFCA5F8
sSHFPRecord: 1 2 F1CED1E2BB3D2421DFCCFA357958EC7DBCD25020B9EEAF16EDCDB187 F00C1A47
sSHFPRecord: 2 1 03CC3DA9A493A574330982518A0F589E9EFD02C3
sSHFPRecord: 2 2 6D531A963F428133DC7F660FD5570F3B545F6275F8E1D0E58ABC6DCE 5A73222A
sSHFPRecord: 3 1 2C6A937EC28844BBEB841D54853BAFEE4A8A755E
sSHFPRecord: 3 2 1269E5F6839116F21BD9878749650046B2D8C97E37FAC0665A2BAF45 CF5951C1
sSHFPRecord: 4 1 D4BC390CFB5B878FEFF0788A08C4FF240B08BE31
sSHFPRecord: 4 2 63BF392676BC2A4B310B2B798BD4BAA80D108F1A3DBE17638971D389 83E96AD6
dNSTTL: 1200

dn: idnsserverid=server.ipa.test,cn=servers,cn=dns,dc=ipa,dc=test
idnsServerId: server.ipa.test
idnsSOAmName: server.ipa.test.
objectClass: top
objectClass: idnsServerConfigObject
idnsForwarders: 10.2.32.1
idnsForwardPolicy: only

dn: idnsname=_ldap._tcp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _ldap._tcp
sRVRecord: 0 100 389 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _ldap._tcp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kerberos._tcp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kerberos._tcp
sRVRecord: 0 100 88 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kerberos._tcp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kerberos._udp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kerberos._udp
sRVRecord: 0 100 88 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kerberos._udp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kerberos-master._tcp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kerberos-master._tcp
sRVRecord: 0 100 88 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kerberos-master._tcp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kerberos-master._udp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kerberos-master._udp
sRVRecord: 0 100 88 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kerberos-master._udp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kpasswd._tcp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kpasswd._tcp
sRVRecord: 0 100 464 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kpasswd._tcp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kpasswd._udp,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kpasswd._udp
sRVRecord: 0 100 464 server.ipa.test.
objectClass: top
objectClass: idnsrecord
objectClass: idnsTemplateObject
idnsTemplateAttribute;cnamerecord: _kpasswd._udp.\{substitutionvariable_ipalocation\}._locations

dn: idnsname=_kpasswd,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: _kpasswd
URIRecord: 0 100 "krb5srv:m:tcp:server.ipa.test."
URIRecord: 0 100 "krb5srv:m:udp:server.ipa.test."
objectClass: top
objectClass: idnsrecord

dn: idnsname=ipa-ca,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test
idnsName: ipa-ca
aRecord: 10.0.138.246
aAAARecord: 2620:52:0:88:f816:3eff:febe:8d9e
objectClass: top
objectClass: idnsrecord

mreynolds389 · 2022-05-16T12:22:34Z

@flo-renaud to confirm, which filter is not working? The first one, the second, or both? I need to reproduce this outside of IPA so I need to know exactly what is failing.

flo-renaud · 2022-05-16T12:40:40Z

@mreynolds389
the first search is returning 1 entry instead of 2.

Firstyear · 2022-05-18T03:03:38Z

I think I've worked it out. the fault isn't in the filter optimiser, it's a fault in freeipa.

What's occuring is that the query optimiser is re-arranging the logically equivalent query from:

(|(objectClass=idnsConfigObject)(&(objectClass=idnsServerConfigObject)(idnsServerId=server.ipa.test)))

(|(objectClass=idnsConfigObject)(&(idnsserverid=server.ipa.test)(objectClass=idnsServerConfigObject)))

Note the promotion of idnsserverid in the second or condition. This means it get evaluated first.

This value is NOT found in the indexes OR our schema, which means it gets rejected. I turned up logging and added some extra info:

[18/May/2022:12:57:05.042213867 +1000] - DEBUG - str2simple - "objectclass=referral"
[18/May/2022:12:57:05.042746553 +1000] - DEBUG - ldbm_back_search - Optimised SUB filter to - (|(|(objectClass=idnsConfigObject)(&(idnsserverid=server.ipa.test)(objectClass=idnsServerConfigObject)))(objectclass=referral))
[18/May/2022:12:57:05.043210778 +1000] - DEBUG - filter_candidates_ext - 	OR
[18/May/2022:12:57:05.043598898 +1000] - DEBUG - filter_candidates_ext - 	OR
[18/May/2022:12:57:05.044128175 +1000] - DEBUG - filter_candidates_ext - 	EQUALITY
[18/May/2022:12:57:05.044493468 +1000] - DEBUG - ava_candidates - =>
[18/May/2022:12:57:05.044898844 +1000] - DEBUG - ava_candidates -    objectClass=idnsConfigObject
[18/May/2022:12:57:05.045271131 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - =>
[18/May/2022:12:57:05.045778673 +1000] - DEBUG - slapi_attr_assertion2keys_ava_sv - => 0
[18/May/2022:12:57:05.046241354 +1000] - DEBUG - filter_candidates_ext - 	AND
[18/May/2022:12:57:05.046726250 +1000] - DEBUG - filter_candidates_ext - 	EQUALITY
[18/May/2022:12:57:05.047210513 +1000] - DEBUG - ava_candidates - =>
[18/May/2022:12:57:05.047584759 +1000] - DEBUG - ava_candidates -    idnsserverid=server.ipa.test
[18/May/2022:12:57:05.048076724 +1000] - DEBUG - ava_candidates - WARNING - filter contains an INVALID attribute!
[18/May/2022:12:57:05.048501200 +1000] - DEBUG - ava_candidates - REJECTING invalid filter per policy!
[18/May/2022:12:57:05.049026752 +1000] - DEBUG - filter_candidates_ext - 	EQUALITY

Previously, what would have occurred is that you were relying on a quirk and a lot of luck. The query would evaluate &(objectClass=idnsServerConfigObject)(idnsServerId=server.ipa.test) first, and because objectClass=idnsServerConfigObject was below the FILTER_TEST_THRESHOLD of I think 10 entries, it would shortcut return, meaning that the invalid idnsServerId attribute would never be consulted. This then would trigger the filter test which DOES allow invalid attributes (since this is denial of service safe).

However in this case because idnsserverid is promoted and does not exist in the schema, then the default schema protection policy applies to prevent denial of service attacks per SLAPI_WARN_SAFE.

This means that it actually also would have triggered a warning in the results and access log per schema.c:

"slapi_pblock_set_result_text_if_empty(pb, "Invalid attribute in filter - results may not be complete.");"

And as we have here - the results are not complete, because the schema is likely missing the attribute idnsserverid, and thus we can not index it or safely search for it.

Had you had a situation where you had more than 10 idnsServerConfigObject's, you also would have silently begun to lose results even pre-filter optimisation.

Firstyear · 2022-05-18T03:05:24Z

Which means btw, the resolution is that you need to check that you have everything in the ipa schema correctly setup and defined, because it looks like in this situation we are correctly rejecting the query as that attribute is undefined to our schemas knowledge.

Firstyear · 2022-05-18T03:08:04Z

Or alternately, you need to globally set freeipa to have "warn-invalid" https://access.redhat.com/documentation/en-us/red_hat_directory_server/11/html-single/configuration_command_and_file_reference/index#cnconfig-nsslapd-verify-filter-schema

If you want to go the other way, set reject-invalid, and do your full CI suite to detect all the invalid queries that have been assumed to work. :)

flo-renaud · 2022-05-18T07:55:02Z

Hi @Firstyear
the attribute idnsserverid and its associated objectclass idnsServerConfigObject are defined in /usr/share/ipa/60ipadns.ldif which gets loaded in IPA use case, but the attribute is not indexed. Would the lack of index suffice to explain the issue?

Firstyear · 2022-05-18T08:00:14Z

Yes it would. Because 389-ds' backend can not distinguish between "no index" and "empty index" so it always returns an empty result set. Can you trying indexing that attribute?

Firstyear · 2022-05-18T08:02:19Z

(At least, that's what I remember, I'm not looking at the code right now, so yes, please try indexing it)

flo-renaud · 2022-05-19T18:07:20Z

@Firstyear
I tried by adding the following:

dn: cn=idnsserverid,cn=index,cn=userRoot,cn=ldbm database,cn=plugins,cn=config
cn: idnsserverid
nsIndexType: eq
nsSystemIndex: false
objectClass: nsIndex
objectClass: top

but I still get the same result.

Without the index and with nsslapd-verify-filter-schema: warn-invalid I don't get any search labeled with notes=F in the access log. This shows that the idnsserverid is properly defined in the schema.

mreynolds389 · 2022-05-19T19:07:14Z

@flo-renaud tonight's COPR build should have new "search filter" logging in it. Would it be possible to enable filter logging (see below) and run the test again with that new build:

dn: cn=config
changetype: modify
replace: nsslapd-errorlog-level
nsslapd-errorlog-level: 32

mreynolds389 · 2022-05-23T14:41:29Z

Having a hard time getting IPA to install on a beaker system using a custom hostname :-(

If I leave things as is, using the default beaker hostname, but use "--domain ipa.test --realm IPA.TEST" everything works fine:

# host hpe-bl420cgen8-01.hpe1.lab.eng.bos.redhat.com localhost
Using domain server:
Name: localhost
Address: ::1#53
Aliases: 

hpe-bl420cgen8-01.hpe1.lab.eng.bos.redhat.com has address 10.16.203.15
hpe-bl420cgen8-01.hpe1.lab.eng.bos.redhat.com has IPv6 address 2620:52:0:10cb:3ed9:2bff:fef6:9aa8

If I try hacking /etc/hosts to use server.ipa.test, the IPA server install fails immediately. Looks like the beaker system is now hosed as everything is failing now. Spent 2 hours on this already and to have to start all over again is a bit frustrating...

So I don't know if its my setup, or what. Perhaps I need someone from the IPA to reproduce this and give me access to their machine so I can investigate it? @flo-renaud thoughts?

flo-renaud · 2022-05-23T16:14:54Z

Hi @mreynolds389
On fedora I'm doing the 3 following steps to change the machine hostname:

hostnamectl set-hostname server.ipa.test
export HOSTNAME=server.ipa.test
echo "$IP server.ipa.test" >> /etc/hosts
(Replace with the right IP address)

Please let me know if it helps installing IPA.

mreynolds389 · 2022-05-23T18:22:29Z

Thanks @flo-renaud that did the trick (I was missing the hostnamectl part)!

So I could reproduce the error from the description of this ticket, but when I run that "host" command it's not even hitting the directory server. DS is completely idle, and zero operations are sent against it. No binds, no searches, nothing. So I'm not seeing a DS problem - perhaps IPA is not working as needed to reproduce the DS issue on a lab machine?

mreynolds389 · 2022-05-23T19:02:44Z

Ok, so the search that is causing issues happens at server startup, not when "host" is called. Investigating...

flo-renaud · 2022-06-20T06:37:18Z

The latest IPA CI run doesn't show the issue any more, closing this issue as fixed.

flo-renaud added the needs triage The issue will be triaged during scrum label May 9, 2022

mreynolds389 mentioned this issue May 16, 2022

Issue 5170 - BUG - ldapsubentries were incorrectly returned #5285

Merged

mreynolds389 mentioned this issue May 17, 2022

Filter optimiser #5170

Closed

mreynolds389 self-assigned this May 23, 2022

mreynolds389 added this to the 2.0.0 milestone May 23, 2022

abbra mentioned this issue Jun 7, 2022

Nightly test failure in IPA server installation #5332

Closed

flo-renaud closed this as completed Jun 20, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Regression related to sync_repl in ipa nightly tests #5289

Regression related to sync_repl in ipa nightly tests #5289

flo-renaud commented May 9, 2022

progier389 commented May 9, 2022

flo-renaud commented May 15, 2022

mreynolds389 commented May 15, 2022

flo-renaud commented May 16, 2022

mreynolds389 commented May 16, 2022

flo-renaud commented May 16, 2022

Firstyear commented May 18, 2022 •

edited

Firstyear commented May 18, 2022

Firstyear commented May 18, 2022 •

edited

flo-renaud commented May 18, 2022

Firstyear commented May 18, 2022

Firstyear commented May 18, 2022

flo-renaud commented May 19, 2022

mreynolds389 commented May 19, 2022

mreynolds389 commented May 23, 2022

flo-renaud commented May 23, 2022

mreynolds389 commented May 23, 2022

mreynolds389 commented May 23, 2022

flo-renaud commented Jun 20, 2022

Regression related to sync_repl in ipa nightly tests #5289

Regression related to sync_repl in ipa nightly tests #5289

Comments

flo-renaud commented May 9, 2022

progier389 commented May 9, 2022

flo-renaud commented May 15, 2022

mreynolds389 commented May 15, 2022

flo-renaud commented May 16, 2022

mreynolds389 commented May 16, 2022

flo-renaud commented May 16, 2022

Firstyear commented May 18, 2022 • edited

Firstyear commented May 18, 2022

Firstyear commented May 18, 2022 • edited

flo-renaud commented May 18, 2022

Firstyear commented May 18, 2022

Firstyear commented May 18, 2022

flo-renaud commented May 19, 2022

mreynolds389 commented May 19, 2022

mreynolds389 commented May 23, 2022

flo-renaud commented May 23, 2022

mreynolds389 commented May 23, 2022

mreynolds389 commented May 23, 2022

flo-renaud commented Jun 20, 2022

Firstyear commented May 18, 2022 •

edited

Firstyear commented May 18, 2022 •

edited