#8691 [Tracker] Nightly failure (fc33) in test_winsyncmigrate.py: ipa-replica-manage connect --winsync error
Closed: fixed 2 years ago by frenaud. Opened 3 years ago by frenaud.

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 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


The issue is also happening without updates-testing, see PR #740 [testing_master_latest] on fedora33.

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.

Metadata Update from @frenaud:
- Issue tagged with: tracker

3 years ago

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.

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

2 years ago

Metadata Update from @frenaud:
- Custom field on_review adjusted to https://github.com/freeipa/freeipa/pull/5819

2 years ago

master:

  • 25f42c3 freeipa.spec: bump 389-ds version

ipa-4-9:

  • 6eb5353 freeipa.spec: bump 389-ds version

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

2 years ago

Login to comment on this ticket.

Metadata