#9069 Nightly test failure (updates-testing) in test_winsyncmigrate.py::TestWinsyncMigrate
Closed: fixed by frenaud. Opened by frenaud.

The nightly test test_winsyncmigrate.py::TestWinsyncMigrate is failing while establishing a winsync replication agreement, when the updates-testing repository is enabled.
See PR #1389 with the following logs and report:

cls = <class 'ipatests.test_integration.test_winsyncmigrate.TestWinsyncMigrate'>
mh = <pytest_multihost.plugin.MultihostFixture object at 0x7ff434c6d180>
    @classmethod
    def install(cls, mh):
        super(TestWinsyncMigrate, cls).install(mh)
        cls.ad = cls.ads[0]
        cls.trust_test_user = '%s@%s' % (cls.ad_user, cls.ad.domain.name)
        tasks.configure_dns_for_trust(cls.master, cls.ad)
        tasks.install_adtrust(cls.master)
        cls.create_test_objects()
>       establish_winsync_agreement(cls.master, cls.ad)
test_integration/test_winsyncmigrate.py:82: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
test_integration/test_winsyncmigrate.py:38: in establish_winsync_agreement
    master.run_command([
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = <ipatests.pytest_ipa.integration.host.Host master.ipa.test (master)>
argv = ['ipa-replica-manage', 'connect', '--winsync', '--binddn', 'cn=Administrator,cn=users,dc=ad,dc=test', '--bindpw', ...]
set_env = True, stdin_text = None, log_stdout = True, raiseonerr = True
cwd = None, bg = False, encoding = 'utf-8', ok_returncode = 0
    def run_command(self, argv, set_env=True, stdin_text=None,
                    log_stdout=True, raiseonerr=True,
                    cwd=None, bg=False, encoding='utf-8', ok_returncode=0):
        """Wrapper around run_command to log stderr on raiseonerr=True
        :param ok_returncode: return code considered to be correct,
                              you can pass an integer or sequence of integers
        """
        result = super().run_command(
            argv, set_env=set_env, stdin_text=stdin_text,
            log_stdout=log_stdout, raiseonerr=False, cwd=cwd, bg=bg,
            encoding=encoding
        )
        # in FIPS mode SSH may print noise to stderr, remove the string
        # "FIPS mode initialized" + optional newline.
        result.stderr_bytes = FIPS_NOISE_RE.sub(b'', result.stderr_bytes)
        try:
            result_ok = result.returncode in ok_returncode
        except TypeError:
            result_ok = result.returncode == ok_returncode
        if not result_ok and raiseonerr:
            result.log.error('stderr: %s', result.stderr_text)
>           raise subprocess.CalledProcessError(
                result.returncode, argv,
                result.stdout_text, result.stderr_text
            )
E           subprocess.CalledProcessError: Command '['ipa-replica-manage', 'connect', '--winsync', '--binddn', 'cn=Administrator,cn=users,dc=ad,dc=test', '--bindpw', 'Secret123', '--password', 'Secret.123', '--cacert', '/tmp/tmp.TpQiL0PavA', '--passsync', 'dummy', 'ad-root.ad.test', '-v']' returned non-zero exit status 1.

Output of the command:

DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:513 RUN ['ipa-replica-manage', 'connect', '--winsync', '--binddn', 'cn=Administrator,cn=users,dc=ad,dc=test', '--bindpw', 'Secret123', '--password', 'Secret.123', '--cacert', '/tmp/tmp.TpQiL0PavA', '--passsync', 'dummy', 'ad-root.ad.test', '-v']
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 ipa: INFO: AD Suffix is: DC=ad,DC=test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 Added CA certificate /tmp/tmp.TpQiL0PavA to certificate database for master.ipa.test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 The user for the Windows PassSync service is uid=passsync,cn=sysaccounts,cn=etc,dc=ipa,dc=test
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 Adding Windows PassSync system account
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 Traceback (most recent call last):
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipapython/ipaldap.py", line 1090, in error_handler
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     yield
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipapython/ipaldap.py", line 1662, in add_entry
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     self.conn.add_s(str(entry.dn), list(attrs.items()))
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 439, in add_s
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     return self.add_ext_s(dn,modlist,None,None)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 425, in add_ext_s
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.timeout)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 764, in result3
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     resp_type, resp_data, resp_msgid, decoded_resp_ctrls, retoid, retval = self.result4(
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 774, in result4
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 340, in _ldap_call
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     reraise(exc_type, exc_value, exc_traceback)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/compat.py", line 46, in reraise
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     raise exc_value
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/site-packages/ldap/ldapobject.py", line 324, in _ldap_call
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     result = func(*args,**kwargs)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 ldap.UNWILLING_TO_PERFORM: {'msgtype': 105, 'msgid': 18, 'result': 53, 'desc': 'Server is unwilling to perform', 'ctrls': []}
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 During handling of the above exception, another exception occurred:
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 Traceback (most recent call last):
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/sbin/ipa-replica-manage", line 1613, in <module>
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     main(options, args)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/sbin/ipa-replica-manage", line 1570, in main
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     add_link(realm, replica1, replica2, dirman_passwd, options)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/sbin/ipa-replica-manage", line 1143, in add_link
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     repl1.setup_winsync_replication(replica2,
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipaserver/install/replication.py", line 1349, in setup_winsync_replication
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     self.setup_agreement(self.conn, ad_dc_name,
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipaserver/install/replication.py", line 888, in setup_agreement
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     a_conn.add_entry(entry)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipapython/ipaldap.py", line 1660, in add_entry
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     with self.error_handler():
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib64/python3.10/contextlib.py", line 153, in __exit__
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     self.gen.throw(typ, value, traceback)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557   File "/usr/lib/python3.10/site-packages/ipapython/ipaldap.py", line 1152, in error_handler
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557     raise errors.DatabaseError(desc=desc, info=info)
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 ipalib.errors.DatabaseError: Server is unwilling to perform: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:557 Unexpected error: Server is unwilling to perform: 
DEBUG    ipatests.pytest_ipa.integration.host.Host.master.cmd90:transport.py:217 Exit code: 1
ERROR    ipatests.pytest_ipa.integration.host.Host.master.cmd90:host.py:201 stderr: ipa: INFO: AD Suffix is: DC=ad,DC=test

The directory server returns error=53 (unwilling to perform) on the operation adding the windows replication agreement:

[22/Dec/2021:14:54:50.313481432 +0000] conn=4 op=17 ADD dn="cn=meToad-root.ad.test,cn=replica,cn=dc\3Dipa\2Cdc\3Dtest,cn=mapping tree,cn=config"
[22/Dec/2021:14:54:50.321542434 +0000] conn=4 op=17 RESULT err=53 tag=105 nentries=0 wtime=0.000367177 optime=0.008066724 etime=0.008430591

Dirsrv error log contains the following:

[22/Dec/2021:14:54:50.316125333 +0000] - ERR - NSMMReplicationPlugin - agmt_new_from_entry: failed to initialise windows replicationagreement "agmt="cn=meToad-root.ad.test" (ad-root:389)" - replica is not a supplier (may be hub or consumer).
[22/Dec/2021:14:54:50.317510539 +0000] - ERR - NSMMReplicationPlugin - To proceed, you MUST promote this server to a supplier with: dsconf INSTANCENAME replication promote --suffix "dc=ipa,dc=test" --newrole supplier --replica-id=NEW_REPLICA_ID
[22/Dec/2021:14:54:50.318917730 +0000] - ERR - NSMMReplicationPlugin - agmt_new_from_entry - Failed to parse agreement, skipping.
[22/Dec/2021:14:54:50.319904477 +0000] - ERR - NSMMReplicationPlugin - agmtlist_add_callback - Can't start agreement "cn=meToad-root.ad.test,cn=replica,cn=dc\3Dipa\2Cdc\3Dtest,cn=mapping tree,cn=config"
[22/Dec/2021:14:54:50.324904645 +0000] - ERR - ipa_sidgen_add_post_op - [file ipa_sidgen.c, line 128]: Missing target entry.

The regression seems to be introduced with 389-ds-base-2.0.12-1.fc35.


Companion issue on 389-ds-base side: https://github.com/389ds/389-ds-base/issues/5079

The issue has been fixed in 389-ds master branch, 389-ds 2.0 branch and 389-ds 1.4.4 branch.
PRCI will run the test next week-end using the copr repo @389ds/389-ds-base-nightly and we'll be able to confirm whether the issue is fixed.

test failure seen in testing_master_latest PR 1440 report

test faliure seen in testing_master_latest PR 1456 Report

test faliure seen in testing_master_latest_selinux PR 1463 Report

test failure seen in testing_master_latest_selinux PR report

test failure seen in testing_master_latest PR 1471 Report

test failure seen in testing_master_latest PR 1479 Report

test failure seen in testing_master_latest PR 1487 Report

test failure seen in testing_master_latest PR 1495 Report

master:

  • 926b707d319d9f8b4cd9f63cd2418624b1274a90 ipatests: update images for f34 and f35

ipa-4-9:

  • 896d0f351646e6a7c96037cb13957b7be0408776 ipatests: update images for f34 and f35

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

Metadata