#8762 Nightly test failure in test_integration/test_replica_promotion.py/TestReplicaInstallCustodia
Closed: duplicate 3 years ago by frenaud. Opened 3 years ago by mpolovka.

test_integration/test_replica_promotion.py::TestReplicaInstallCustodia::test_replica_install_for_custodia is failing in [testing_ipa-4.9_latest] Nightly PR #771 with an error:

>       tasks.install_replica(replica1, replica2, setup_ca=True,
                              nameservers='master')

test_integration/test_replica_promotion.py:708: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
pytest_ipa/integration/tasks.py:511: in install_replica
    result = replica.run_command(args, raiseonerr=raiseonerr,
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <ipatests.pytest_ipa.integration.host.Host replica0.ipa.test (replica)>
argv = ['ipa-replica-install', '--admin-password', 'Secret.123', '--password', 'Secret.123', '-U', ...]
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-install', '--admin-password', 'Secret.123', '--password', 'Secret.123', '-U', '--setup-ca', '--ip-address', '192.168.122.60', '--realm', 'IPA.TEST', '--domain', 'ipa.test', '--dirsrv-config-file', '/ipatests/ipatests_dse.ldif']' returned non-zero exit status 1.

Furthermore, the logs show

ipa: WARNING: ipa: ERROR: DNS zone with name "122.168.192.in-addr.arpa." already exists

ipa: ERROR: stderr: Lookup failed: Preferred host replica0.ipa.test does not provide DNS.
Could not resolve hostname replica1.ipa.test using DNS. Clients may not function properly. Please check your DNS setup. (Note that this check queries IPA DNS directly and ignores /etc/hosts.)
Lookup failed: Preferred host replica1.ipa.test does not provide CA.
Replica DNS records could not be added on master: Insufficient access: Insufficient 'add' privilege to add the entry 'idnsname=replica0,idnsname=ipa.test.,cn=dns,dc=ipa,dc=test'.
Custodia uses 'master.ipa.test' as master peer.
Failed to configure CA instance
See the installation logs and the following files/directories for more information:
  /var/log/pki/pki-tomcat
CA configuration failed.
The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information

ipareplica install logs don't containt mention of Big Integer.
Full logs


Investigation:
- the test fails while calling ipa-replica-install on replica0 (visible in report.html):

DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 Failed to configure CA instance
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 See the installation logs and the following files/directories for more information:
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557   /var/log/pki/pki-tomcat
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557   [error] RuntimeError: CA configuration failed.
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 CA configuration failed.
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 Your system may be partly configured.
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 The ipa-replica-install command failed. See /var/log/ipareplica-install.log for more information
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 Run /usr/sbin/ipa-server-install --uninstall to clean up.
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:557 
DEBUG    ipatests.pytest_ipa.integration.host.Host.replica0.cmd73:transport.py:217 Exit code: 1
INFO: Waiting for CA subsystem to start (59s)
INFO: Waiting for CA subsystem to start (60s)
ERROR: Exception: CA subsystem did not start after 60s
  File "/usr/lib/python3.9/site-packages/pki/server/pkispawn.py", line 575, in main
    scriptlet.spawn(deployer)
  File "/usr/lib/python3.9/site-packages/pki/server/deployment/scriptlets/configuration.py", line 962, in spawn
    deployer.instance.wait_for_startup(
  File "/usr/lib/python3.9/site-packages/pki/server/deployment/pkihelper.py", line 890, in wait_for_startup
    raise Exception('%s subsystem did not start after %ds' %


2021-03-13T10:32:19Z CRITICAL Failed to configure CA instance
2021-03-13 10:31:15 INFO: Starting server
2021-03-13 10:31:15 DEBUG: Command: systemctl start pki-tomcatd@pki-tomcat.service
2021-03-13 10:31:18 INFO: FIPS mode: False
2021-03-13 10:31:19 INFO: Waiting for CA subsystem to start (1s)
...
2021-03-13 10:32:18 INFO: Waiting for CA subsystem to start (60s)
2021-03-13 10:32:19 ERROR: Exception: CA subsystem did not start after 60s
Mar 13 10:32:22 replica0.ipa.test server[19623]: WARNING: Some of the specified [protocols] are not supported by the SSL engine and have been skipped: [[TLSv1, TLSv1.1]]
Mar 13 10:32:22 replica0.ipa.test server[19623]: SEVERE: Failed to initialize component [Connector[AJP/1.3-8009]]
Mar 13 10:32:22 replica0.ipa.test server[19623]: org.apache.catalina.LifecycleException: Protocol handler initialization failed
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.connector.Connector.initInternal(Connector.java:1049)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.core.StandardService.initInternal(StandardService.java:558)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.core.StandardServer.initInternal(StandardServer.java:1045)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.util.LifecycleBase.init(LifecycleBase.java:136)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.startup.Catalina.load(Catalina.java:724)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.startup.Catalina.load(Catalina.java:746)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/java.lang.reflect.Method.invoke(Method.java:566)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:302)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:472)
Mar 13 10:32:22 replica0.ipa.test server[19623]: Caused by: java.net.BindException: Address already in use
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/sun.nio.ch.Net.bind0(Native Method)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/sun.nio.ch.Net.bind(Net.java:455)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/sun.nio.ch.Net.bind(Net.java:447)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at java.base/sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:227)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.tomcat.util.net.NioEndpoint.initServerSocket(NioEndpoint.java:277)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:241)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.tomcat.util.net.AbstractEndpoint.bindWithCleanup(AbstractEndpoint.java:1193)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.tomcat.util.net.AbstractEndpoint.init(AbstractEndpoint.java:1206)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.coyote.AbstractProtocol.init(AbstractProtocol.java:597)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         at org.apache.catalina.connector.Connector.initInternal(Connector.java:1046)
Mar 13 10:32:22 replica0.ipa.test server[19623]:         ... 13 more

The issue is similar to https://pagure.io/freeipa/issue/8748, closing as duplicate.

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

3 years ago

Login to comment on this ticket.

Metadata