#9153 [Tracker] Nightly test regression with 389ds nightly build in syncrepl
Closed: fixed by frenaud. Opened by frenaud.

The nightly tests using @389ds/389-ds-base-nightly copr repo detected a regression introduced by 389-ds-base-2.2.0-202205050142git90d847426.fc35.x86_64. See for instance the test 389ds-fedora/test_backup_and_restore_TestBackupAndRestore in PRCI #1695 (logs, report).

Test scenario:
- install IPA server with DNS
- run host master.ipa.test localhost to query the server IP address using the local DNS server

The command fails with the following output:

DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:513 RUN ['host', 'master.ipa.test', 'localhost']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Using domain server:
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Name: localhost
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Address: ::1#53
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Aliases: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:557 Host master.ipa.test not found: 3(NXDOMAIN)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd67:transport.py:217 Exit code: 1

The DNS server is relying on syncrepl but we can see errors in /var/named/data/database.log:

08-May-2022 19:12:23.587 info: shutting down automatic empty zones to enable forwarding for domain '.'
08-May-2022 19:12:23.598 info: LDAP configuration for instance 'ipa' synchronized
08-May-2022 19:12:23.612 info: LDAP data for instance 'ipa' are being synchronized, please ignore message 'all zones loaded'
08-May-2022 19:12:23.660 error: mldap_iter_deadnodes_* failed, run rndc reload: partial match
08-May-2022 19:12:23.660 info: 0 master zones from LDAP instance 'ipa' loaded (0 zones defined, 0 inactive, 0 failed to load)
08-May-2022 19:12:23.660 info: 0 master zones is suspicious number, please check access control instructions on LDAP server
08-May-2022 19:12:25.461 error: LDAP error: Can't contact LDAP server: ldap_sync_poll() failed
08-May-2022 19:12:25.461 error: ldap_syncrepl will reconnect in 60 seconds
08-May-2022 19:13:25.468 info: successfully reconnected to LDAP server
08-May-2022 19:13:25.483 info: LDAP configuration for instance 'ipa' synchronized
08-May-2022 19:13:25.489 info: LDAP data for instance 'ipa' are being synchronized, please ignore message 'all zones loaded'
08-May-2022 19:13:25.520 error: mldap_iter_deadnodes_* failed, run rndc reload: partial match
08-May-2022 19:13:52.793 info: unloading DynDB instance 'ipa'
08-May-2022 19:13:52.953 debug 1: calling free_rbtdb(.)
08-May-2022 19:13:52.954 debug 1: done free_rbtdb(.)
08-May-2022 19:13:52.954 info: shutting down automatic empty zones to enable forwarding for domain '.'
08-May-2022 19:13:52.956 debug 1: ldap_sync_search_result
08-May-2022 19:13:52.956 debug 1: sctx state 1 reached
08-May-2022 19:13:52.956 debug 1: sync_barrier_wait(): wait until all events are processed
08-May-2022 19:13:52.956 debug 1: sync_barrier_wait(): barrier reached
08-May-2022 19:13:52.956 debug 1: sync_barrier_wait(): finish reached
08-May-2022 19:13:52.956 debug 1: sctx state 2 reached
08-May-2022 19:13:52.956 debug 1: sync_barrier_wait(): all events were processed
08-May-2022 19:13:52.956 info: LDAP configuration for instance 'ipa' synchronized
08-May-2022 19:13:52.966 info: LDAP data for instance 'ipa' are being synchronized, please ignore message 'all zones loaded'
08-May-2022 19:13:52.966 debug 1: LDAP syncrepl filter = '(|  (objectClass=idnsConfigObject)    (&(objectClass=idnsServerConfigObject)    (idnsServerId=master.ipa.test))(|(objectClass=idnsZone)  (objectClass=idnsForwardZone)  (objectClass=idnsRecord)))'
08-May-2022 19:13:53.006 debug 1: ldap_sync_intermediate 0x50
08-May-2022 19:13:53.006 debug 1: sctx state 3 reached
08-May-2022 19:13:53.006 debug 1: sync_barrier_wait(): wait until all events are processed
08-May-2022 19:13:53.016 debug 1: sync_barrier_wait(): barrier reached
08-May-2022 19:13:53.016 debug 1: sync_barrier_wait(): finish reached
08-May-2022 19:13:53.016 debug 1: sctx state 4 reached
08-May-2022 19:13:53.016 debug 1: sync_barrier_wait(): all events were processed
08-May-2022 19:13:53.016 error: mldap_iter_deadnodes_* failed, run rndc reload: partial match
08-May-2022 19:13:53.016 info: 0 master zones from LDAP instance 'ipa' loaded (0 zones defined, 0 inactive, 0 failed to load)
08-May-2022 19:13:53.016 info: 0 master zones is suspicious number, please check access control instructions on LDAP server
08-May-2022 19:13:54.260 error: bug in ldap_entry_reconstruct(): protocol violation: attempt to reconstruct non-existing entry
08-May-2022 19:13:54.260 error: ldap_sync_search_entry failed: not found

With the build 389-ds-base-2.2.0-202205031357git0ca6689f2.fc35.x86_64 there is no issue, the regression seems to have been introduced with this commit 90d8474


Companion issue logged against 389ds: https://github.com/389ds/389-ds-base/issues/5289

Well still investigating the DS regression, but I foudn a bug in IPA, an ACI has some typoes in it:

dn: cn=dns,dc=ipa,dc=test
...
aci: (targetattr = "*")(version 3.0; acl "Allow read access"; allow (read,sear
 ch,compare) groupdn = "ldap:///cn=Read DNS Entries,cn=permissions,cn=pbac,dc=
 ipa,dc=test" or userattr = "parent[0,1].managedby#GROUPDN";)

The group DN is actually:

cn=system: Read DNS Entries,cn=permissions,cn=pbac,dc=ipa,dc=test

Not

cn=Read DNS Entries,cn=permissions,cn=pbac,dc=ipa,dc=test

So this ACI is basically being ignored, and it should be fixed on the IPA side.

Ok...

So once the ACI is fixed for the proper group dn everything works with the DS RFE. Turns out that ACI I mentioned was never used, (it never worked as intended). So the filter optimization RFE in DS exposed the IPA invalid ACI.

But how do we proceed? If IPA fixes its faulty ACI everything works. Yes with the filter optimization code we are now checking the filter differently - so that is a change in behavior, but IPA would never had noticed it if it had the correct aci in place to begin with.

Now IPA had an ACI to deal with this search - so it was trying to do the right thing. But it was a lucky fluke that a completely different ACI ("Admin can manage any entry") was allowing the operation to succeed. With the filter optimizer that old unrelated aci ("Admin can manage any entry") is now correctly ignoring that search on "cn=dns,dc=ipa,dc=test".

Let's fix IPA side. We have plan for a release next week so it would be timely.

After further investigation, while trying to write a testcase for this in DS, I think we still have a regression in DS, because there is an IPA aci that should still be allowing access to "cn=dns,dc=ipa,dc=test":

aci: (targetfilter="(&(objectclass=nsContainer)(!(objectclass=krbPwdPolicy)))"
 )(target!="ldap:///cn=masters,cn=ipa,cn=etc,dc=ipa,dc=test")(targetattr="obje
 ctclass || cn")(version 3.0; acl "Anonymous read access to containers"; allow
 (read, search, compare) userdn = "ldap:///anyone";)

IPA should still fix that ACI with the wrong group DN, but it looks like the main problem is still in DS.

@frenaud - ok we might have fixed this, can you test:

https://copr.fedorainfracloud.org/coprs/g/389ds/389-ds-base-nightly/build/4460276/

Even if this work, IPA should still fix that ACI :-)

Hi @mreynolds
Thanks for the test build. The tests are running at https://github.com/freeipa-pr-ci2/freeipa/pull/1753 with your build.
I'll investigate the ACI issue (we have upgrade code that should take care of it, not sure what is missing there).

@mreynolds
the tests look good, we have some failures but they are all related to known issues. I think your patch properly fixes the issue.

The ACI issue is tracked at https://pagure.io/freeipa/issue/9173 (new installations define the faulty ACI mentioned in https://pagure.io/freeipa/issue/9153#comment-799272 , but after running ipa-server-upgrade this ACI is replaced by the expected one), with a tentative fix at https://github.com/freeipa/freeipa/pull/6298

Issue fixed by 389-ds, see for instance PR #1797 with the successful run of test_backup_and_restore_TestBackupAndRestore: Details

Metadata Update from @frenaud:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

Metadata