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.
test_integration/test_replication_layouts.py::TestCompleteTopologyWithCAKRA::test_complete_topology_with_ca_kra
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.
ipatests.pytest_ipa.integration.host.Host.replica1.cmd90:host.py:201 stderr: ipa: ERROR: Configured time limit exceeded
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
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.