#9745 Nightly-previous-selinux ipa-4-10 failure in test_integration/test_replication_layouts.py::TestCompleteTopologyWithCAKRA::test_complete_topology_with_ca_kra
Opened 2 months ago by dhanina. Modified 2 months ago

The nightly-previous-selinux ipa-4-10 test test_integration/test_replication_layouts.py::TestCompleteTopologyWithCAKRA::test_complete_topology_with_ca_kra fails at subprocess.CalledProcessError: Command '['ipa', 'topologysegment-add', 'domain', 'replica1.ufreeipa.test-to-replica3.ufreeipa.test', '--leftnode=replica1.ufreeipa.test', '--rightnode=replica3.ufreeipa.test']' returned non-zero exit status 1.

There's also ipatests.pytest_ipa.integration.host.Host.replica1.cmd90:host.py:201 stderr: ipa: ERROR: Configured time limit exceeded going on.

Possibly can be insta-closed, as it seems to be the continuation of https://pagure.io/freeipa/issue/8182. I suggest observing as of right now.

self = <ipatests.test_integration.test_replication_layouts.TestCompleteTopologyWithCAKRA object at 0x7f1e4cf78650>

    def test_complete_topology_with_ca_kra(self):
>       tasks.install_topo('complete', self.master, self.replicas, [],
                           setup_replica_cas=True, setup_replica_kras=True)

self       = <ipatests.test_integration.test_replication_layouts.TestCompleteTopologyWithCAKRA object at 0x7f1e4cf78650>

test_integration/test_replication_layouts.py:120: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
pytest_ipa/integration/tasks.py:1447: in install_topo
    connect_replica(parent, child)
        child      = <ipatests.pytest_ipa.integration.host.Host replica3.ufreeipa.test (replica)>
        clients    = []
        clients_extra_args = ()
        domain_level = None
        installed  = {<ipatests.pytest_ipa.integration.host.Host master.ufreeipa.test (master)>, <ipatests.pytest_ipa.integration.host.Host...t.Host replica3.ufreeipa.test (replica)>, <ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>}
        master     = <ipatests.pytest_ipa.integration.host.Host master.ufreeipa.test (master)>
        parent     = <ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>
        random_serial = False
        replicas   = [<ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>, <ipatests.pytest_ipa.integration.host.Host replica2.ufreeipa.test (replica)>, <ipatests.pytest_ipa.integration.host.Host replica3.ufreeipa.test (replica)>]
        setup_replica_cas = True
        setup_replica_kras = True
        skip_master = False
        topo       = 'complete'
pytest_ipa/integration/tasks.py:1040: in connect_replica
    master.run_command(["ipa", "topologysegment-add", database,
        database   = 'domain'
        domain_level = 1
        master     = <ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>
        replica    = <ipatests.pytest_ipa.integration.host.Host replica3.ufreeipa.test (replica)>
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>
argv = ['ipa', 'topologysegment-add', 'domain', 'replica1.ufreeipa.test-to-replica3.ufreeipa.test', '--leftnode=replica1.ufreeipa.test', '--rightnode=replica3.ufreeipa.test']
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', 'topologysegment-add', 'domain', 'replica1.ufreeipa.test-to-replica3.ufreeipa.test', '--leftnode=replica1.ufreeipa.test', '--rightnode=replica3.ufreeipa.test']' returned non-zero exit status 1.

__class__  = <class 'ipatests.pytest_ipa.integration.host.Host'>
argv       = ['ipa', 'topologysegment-add', 'domain', 'replica1.ufreeipa.test-to-replica3.ufreeipa.test', '--leftnode=replica1.ufreeipa.test', '--rightnode=replica3.ufreeipa.test']
bg         = False
cwd        = None
encoding   = 'utf-8'
log_stdout = True
ok_returncode = 0
raiseonerr = True
result     = <pytest_multihost.transport.SSHCommand object at 0x7f1e4c2461d0>
result_ok  = False
self       = <ipatests.pytest_ipa.integration.host.Host replica1.ufreeipa.test (replica)>
set_env    = True
stdin_text = None

pytest_ipa/integration/host.py:202: CalledProcessError

Logs
Artifacts


Metadata Update from @dhanina:
- Issue tagged with: test-failure

2 months ago

After digging a little bit deeper this issue is also prevalent in yet another test, at it all boils down to pki and LDAP issues.

pki log

2025-02-13 09:32:09 [AuthorityMonitor] SEVERE: LdapBoundConnFactory: Unable to connect to LDAP server: Unable to create socket: java.net.ConnectException: Connection refused
netscape.ldap.LDAPException: Unable to create socket: java.net.ConnectException: Connection refused (-1)

This is fine. Replica installation restarts directory server process several times. In this particular one, we see

2025-02-13T09:31:59Z DEBUG stderr=
2025-02-13T09:31:59Z DEBUG Upgrading IPA:. Estimated time: 1 minute 30 seconds
2025-02-13T09:31:59Z DEBUG   [1/10]: stopping directory server
2025-02-13T09:31:59Z DEBUG Destroyed connection context.ldap2_140161569089680
2025-02-13T09:31:59Z DEBUG Starting external process
2025-02-13T09:31:59Z DEBUG args=['/bin/systemctl', 'stop', 'dirsrv@UFREEIPA-TEST.service']
2025-02-13T09:32:07Z DEBUG Process finished, return code=0

In DS logs:

[13/Feb/2025:09:31:59.253678182 +0000] - INFO - op_thread_cleanup - slapd shutting down - signaling operation threads - op stack size 1 max work q size 2 max work q stack size 2

so PKI loses its connection:

2025-02-13 09:32:01 [profileChangeMonitor] SEVERE: Profile change monitor: Caught exception: netscape.ldap.LDAPException: Server or network error (81)
netscape.ldap.LDAPException: Server or network error (81)

It eventually recovers, at around 09:32:33, but something fails at around 09:32:55 which we don't see in the log because it ends at 09:32:49:

2025-02-13 09:32:49 [ajp-nio-127.0.0.1-8009-exec-3] INFO: PKIService: Response class: InstallToken

this is probably a response for us calling

DEBUG: Command: pki -d /etc/pki/pki-tomcat/alias -f /etc/pki/pki-tomcat/password.conf -U https://master.ufreeipa.test:443 kra-range-request request --install-token /tmp/tmp0wmdooaw/install-token --output-format json --debug

But we don't have the rest of the logs, they weren't flushed to disk.

Log in to comment on this ticket.

Metadata