The nightly test test_integration/test_winsyncmigrate.py::TestWinsyncMigrate::test_preconditions failed in PR #690 [testing_master_testing_selinux] that is run on fedora 33+ updates-testing enabled + selinux in enforcing mode.
test_integration/test_winsyncmigrate.py::TestWinsyncMigrate::test_preconditions
Test logs and report:
cls = <class 'ipatests.test_integration.test_winsyncmigrate.TestWinsyncMigrate'> mh = <pytest_multihost.plugin.MultihostFixture object at 0x7fd7c70719d0> @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.OCf3xgAY5f', '--passsync', 'dummy', 'ad-root.ad.test', '-v']' returned non-zero exit status 1. pytest_ipa/integration/host.py:200: CalledProcessError
The test failed in the setup, when establishing the winsync replication agreement:
RUN ['ipa-replica-manage', 'connect', '--winsync', '--binddn', 'cn=Administrator,cn=users,dc=ad,dc=test', '--bindpw', 'Secret123', '--password', 'Secret.123', '--cacert', '/tmp/tmp.OCf3xgAY5f', '--passsync', 'dummy', 'ad-root.ad.test', '-v'] RUN ['ipa-replica-manage', 'connect', '--winsync', '--binddn', 'cn=Administrator,cn=users,dc=ad,dc=test', '--bindpw', 'Secret123', '--password', 'Secret.123', '--cacert', '/tmp/tmp.OCf3xgAY5f', '--passsync', 'dummy', 'ad-root.ad.test', '-v'] ipa: INFO: AD Suffix is: DC=ad,DC=test Added CA certificate /tmp/tmp.OCf3xgAY5f to certificate database for master.ipa.test Traceback (most recent call last): File "/usr/lib/python3.9/site-packages/ipapython/ipaldap.py", line 1085, in error_handler yield File "/usr/lib/python3.9/site-packages/ipapython/ipaldap.py", line 1657, in add_entry self.conn.add_s(str(entry.dn), list(attrs.items())) File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 439, in add_s return self.add_ext_s(dn,modlist,None,None) File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 425, in add_ext_s resp_type, resp_data, resp_msgid, resp_ctrls = self.result3(msgid,all=1,timeout=self.timeout) File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 764, in result3 resp_type, resp_data, resp_msgid, decoded_resp_ctrls, retoid, retval = self.result4( File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 774, in result4 ldap_result = self._ldap_call(self._l.result4,msgid,all,timeout,add_ctrls,add_intermediates,add_extop) File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 340, in _ldap_call reraise(exc_type, exc_value, exc_traceback) File "/usr/lib64/python3.9/site-packages/ldap/compat.py", line 46, in reraise raise exc_value File "/usr/lib64/python3.9/site-packages/ldap/ldapobject.py", line 324, in _ldap_call result = func(*args,**kwargs) ldap.OPERATIONS_ERROR: {'msgtype': 105, 'msgid': 6, 'result': 1, 'desc': 'Operations error', 'ctrls': [], 'info': 'Invalid DN'} During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/usr/sbin/ipa-replica-manage", line 1621, in <module> main(options, args) File "/usr/sbin/ipa-replica-manage", line 1578, in main add_link(realm, replica1, replica2, dirman_passwd, options) File "/usr/sbin/ipa-replica-manage", line 1151, in add_link repl1.setup_winsync_replication(replica2, File "/usr/lib/python3.9/site-packages/ipaserver/install/replication.py", line 1337, in setup_winsync_replication self.basic_replication_setup(self.conn, replica_id, File "/usr/lib/python3.9/site-packages/ipaserver/install/replication.py", line 1213, in basic_replication_setup self.add_replication_manager(conn, repldn, replpw) File "/usr/lib/python3.9/site-packages/ipaserver/install/replication.py", line 461, in add_replication_manager conn.add_entry(ent) File "/usr/lib/python3.9/site-packages/ipapython/ipaldap.py", line 1657, in add_entry self.conn.add_s(str(entry.dn), list(attrs.items())) File "/usr/lib64/python3.9/contextlib.py", line 135, in __exit__ self.gen.throw(type, value, traceback) File "/usr/lib/python3.9/site-packages/ipapython/ipaldap.py", line 1156, in error_handler raise errors.DatabaseError(desc=desc, info=info) ipalib.errors.DatabaseError: Operations error: Invalid DN Unexpected error: Operations error: Invalid DN Exit code: 1
389ds access log shows that the command failed to add the entry cn=replication manager,cn=config:
[03/Feb/2021:19:46:54.462782376 +0000] conn=6 op=5 ADD dn="cn=replication manager,cn=config" [03/Feb/2021:19:46:54.524714900 +0000] conn=6 op=5 RESULT err=1 tag=105 nentries=0 wtime=0.000111775 optime=0.061935050 etime=0.062040261
and the error log contains:
[03/Feb/2021:19:46:54.527606161 +0000] - ERR - ipa_sidgen_add_post_op - [file ipa_sidgen.c, line 128]: Missing target entry.
Package: 389-ds-base-1.4.4.12-1.fc33.x86_64
another failure. logs
The issue is also happening without updates-testing, see PR #740 [testing_master_latest] on fedora33.
Failure observed: [testing_ipa-4.9_latest] Nightly PR #756 , report
The command fails when doing an ADD equivalent to the following:
# ldapmodify -D cn=directory\ manager -w <pwd> dn: cn=replication manager,cn=config changetype: add objectclass: person userpassword: <pwd> sn: replication manager pseudo user adding new entry "cn=replication manager,cn=config" ldap_add: Operations error (1) additional info: Invalid DN
The test was green with 389-ds-base-1.4.4.11-1.fc33.x86_64: report but started failing with 389-ds-base-1.4.4.12-1.fc33.x86_64: report
With log level =65536, the following messages are logged when doing the ADD:
[24/Mar/2021:18:23:14.705058261 +0100] - DEBUG - PBKDF2_SHA256 - Generated hash {PBKDF2_SHA256}AAAIAAjvDTvTQ16hP2drTCBVkjmhYCANl2KtZoAut/zQWEzr1u5jNTrbbKRnl7xiiI9GtlukSZ1GgnvPCDjejbZA6gMHrp+toSEQ4g4OH2Cflz1hXiuZ0o3IXH+5sq0ZvPBEq5VKZ4Ghg3iAoslbwAn3M5SDj36gxLiy6Zn5+QdZQyVJrjctgLuGDjjyGB4te3ZVPoNTUvbWF41VQpNHLxJh2KuiOw6/ZuGftX0GGyxUFr2rAfwt8rv/NRAY+eh5H5+4PCJRdurgt6ai53Hyl6FATHLB8j2YXzRIfyxIEoPsuojbduLyCz2Z3PlPXqogMJTJ61lB8OmlCMyrP2ppl8J/vwHAZe1u7hncsuePTVdQBIEsJDGqMjS51KJukN1vTlUXMIxkclJzph2pkMHffCOMJZrBqaIcv+wauZyYdL5j4T74 [24/Mar/2021:18:23:14.707663127 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.710032737 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.711809937 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.713509033 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.718118947 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.719805080 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.721543763 +0100] - DEBUG - ipa-range-check - Not an ID range object, nothing to do. [24/Mar/2021:18:23:14.722961248 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.724486843 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.725946593 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.727506232 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.728829386 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.730153494 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.731855295 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.733529359 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.735429901 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.736953721 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.738399960 +0100] - DEBUG - NSUniqueAttr - ADD begin [24/Mar/2021:18:23:14.740281081 +0100] - DEBUG - NSUniqueAttr - preop_add - ADD target=cn=replication manager,cn=config [24/Mar/2021:18:23:14.742500018 +0100] - DEBUG - ipa-sidgen-postop - No existing entries. [24/Mar/2021:18:23:14.743886905 +0100] - DEBUG - ipa-sidgen-postop - Domain SID not available, nothing to do. [24/Mar/2021:18:23:14.745292333 +0100] - DEBUG - ipa-topology-plugin - --> ipa_topo_post_add [24/Mar/2021:18:23:14.746819439 +0100] - DEBUG - ipa-topology-plugin - no entry
Nothing really stands out that could explain the failure.
Opened issue https://github.com/389ds/389-ds-base/issues/4700 on 389-ds side.
Metadata Update from @frenaud: - Issue tagged with: tracker
The issue was fixed on 389-ds-base master and 389-ds-base-1.4.4 branches but we are still waiting for a release containing the fix.
@frenaud the new build including that fix is available: https://koji.fedoraproject.org/koji/taskinfo?taskID=65298461
Current state: Fix is available on fedora 33: 389-ds-base-1.4.4.15-1.fc33 Tentative fix not available on fedora 34: 389-ds-base-2.0.4-1.fc34 was unpushed because of a regression
Waiting for a new build on fc34+ before we bump the 389-ds version in our spec file.
Metadata Update from @frenaud: - Issue assigned to frenaud
Metadata Update from @frenaud: - Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/5819
master:
ipa-4-9:
Metadata Update from @frenaud: - Issue close_status updated to: fixed - Issue status updated to: Closed (was: Open)
Log in to comment on this ticket.