#8815 Nightly test failure in new test test_ipa_cert_fix.py::TestCertFixReplica
Closed: fixed by frenaud. Opened by frenaud.

The new nightly test test_ipa_cert_fix.py::TestCertFixReplica is failing in [testing_master_previous], see for instance PR #855 with the following logs and report:

self = <ipatests.test_integration.test_ipa_cert_fix.TestCertFixReplica object at 0x7fcc6caef0d0>
    def test_renew_expired_cert_replica(self):
        """Test renewal of certificates on replica with ipa-cert-fix
        This is to check that ipa-cert-fix renews the certificates
        on replica
        related: https://pagure.io/freeipa/issue/7885
        """
        move_date(self.master, 'stop', '+3years+1days')
        # wait for cert expiry
        check_status(self.master, 8, "CA_UNREACHABLE")
        self.master.run_command(['ipa-cert-fix', '-v'], stdin_text='yes\n')
        check_status(self.master, 9, "MONITORING")
        # move system date to expire cert on replica
        move_date(self.replicas[0], 'stop', '+3years+1days')
        # RA agent cert will be expired and in CA_UNREACHABLE state
        check_status(self.replicas[0], 1, "CA_UNREACHABLE")
        # renew RA agent cert
>       self.replicas[0].run_command(
            ['ipa-cert-fix', '-v'], stdin_text='yes\n'
        )

This is the first run of the new test introduced by commit https://pagure.io/freeipa/c/99e7ad0fd8d7f621f1d3999c3fb7327802293ec6?branch=master.

@myusuf can you have a look?

HTTP certificate on replica should have been renewed after moving date forward, but it was in state status: NEED_TO_SAVE_CERT. The failure might be caused due the fact that ipa-cert-fix command ran while expected certs (LDAP/HTTP/PKINIT) were not in monitoring state and ipa-cert-fix tried to fix these.

traceback:

ipapython.ipautil: DEBUG: Starting external process
ipapython.ipautil: DEBUG: args=['pki-server', 'cert-fix', '--ldapi-socket', '/run/slapd-IPA-TEST.socket', '--agent-uid', 'ipara', '--cert', 'sslserver', '--cert', 'ca_audit_signing', '--extra-cert', '12']
ipapython.ipautil: DEBUG: Process finished, return code=1
ipapython.ipautil: DEBUG: stdout=
ipapython.ipautil: DEBUG: stderr=INFO: Loading instance: pki-tomcat
INFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf
INFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf
INFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf
INFO: Loading password config: /etc/pki/pki-tomcat/password.conf
INFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
INFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat
INFO: Fixing the following system certs: ['sslserver', 'ca_audit_signing']
INFO: Renewing the following additional certs: ['12']
INFO: Stopping the instance to proceed with system cert renewal
INFO: Configuring LDAP connection for CA
INFO: Setting pkidbuser password via ldappasswd
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
INFO: Selftests disabled for subsystems: ca
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
INFO: Resetting password for uid=ipara,ou=people,o=ipaca
SASL/EXTERNAL authentication started
SASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth
SASL SSF: 0
INFO: Creating a temporary sslserver cert
INFO: Getting sslserver cert info from CS.cfg
INFO: Getting sslserver cert info from NSS database
INFO: Trying to create a new temp cert for sslserver.
INFO: Generate temp SSL certificate
INFO: Getting sslserver cert info from CS.cfg
INFO: Getting sslserver cert info from NSS database
INFO: CSR for sslserver has been written to /tmp/tmp58ptb9uo/sslserver.csr
INFO: Getting signing cert info from CS.cfg
INFO: Getting signing cert info from NSS database
INFO: CA cert written to /tmp/tmp58ptb9uo/ca_certificate.crt
INFO: AKI: 0x5A72C7C839FDFA5E7057273AD7D7B872B7F8419F
INFO: Temp cert for sslserver is available at /etc/pki/pki-tomcat/certs/sslserver.crt.
INFO: Getting sslserver cert info from CS.cfg
INFO: Getting sslserver cert info from NSS database
INFO: Getting sslserver cert info from CS.cfg
INFO: Getting sslserver cert info from NSS database
INFO: Updating CS.cfg with the new certificate
INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
INFO: Starting the instance
Job for pki-tomcatd@pki-tomcat.service canceled.
INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
INFO: Selftests enabled for subsystems: ca
INFO: Restoring LDAP connection for CA
INFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg
INFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg
ipapython.admintool: DEBUG:   File "/usr/lib/python3.8/site-packages/ipapython/admintool.py", line 180, in execute
    return_value = self.run()
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ipa_cert_fix.py", line 144, in run
    run_cert_fix(certs, extra_certs)
  File "/usr/lib/python3.8/site-packages/ipaserver/install/ipa_cert_fix.py", line 366, in run_cert_fix
    ipautil.run(cmd, raiseonerr=True)
  File "/usr/lib/python3.8/site-packages/ipapython/ipautil.py", line 598, in run
    raise CalledProcessError(
ipapython.admintool: DEBUG: The ipa-cert-fix command failed, exception: CalledProcessError: CalledProcessError(Command ['pki-server', 'cert-fix', '--ldapi-socket', '/run/slapd-IPA-TEST.socket', '--agent-uid', 'ipara', '--cert', 'sslserver', '--cert', 'ca_audit_signing', '--extra-cert', '12'] returned non-zero exit status 1: "INFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Fixing the following system certs: ['sslserver', 'ca_audit_signing']\nINFO: Renewing the following additional certs: ['12']\nINFO: Stopping the instance to proceed with system cert renewal\nINFO: Configuring LDAP connection for CA\nINFO: Setting pkidbuser password via ldappasswd\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Selftests disabled for subsystems: ca\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Resetting password for uid=ipara,ou=people,o=ipaca\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Creating a temporary sslserver cert\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Trying to create a new temp cert for sslserver.\nINFO: Generate temp SSL certificate\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: CSR for sslserver has been written to /tmp/tmp58ptb9uo/sslserver.csr\nINFO: Getting signing cert info from CS.cfg\nINFO: Getting signing cert info from NSS database\nINFO: CA cert written to /tmp/tmp58ptb9uo/ca_certificate.crt\nINFO: AKI: 0x5A72C7C839FDFA5E7057273AD7D7B872B7F8419F\nINFO: Temp cert for sslserver is available at /etc/pki/pki-tomcat/certs/sslserver.crt.\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Updating CS.cfg with the new certificate\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Starting the instance\nJob for pki-tomcatd@pki-tomcat.service canceled.\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Selftests enabled for subsystems: ca\nINFO: Restoring LDAP connection for CA\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\n")
ipapython.admintool: ERROR: CalledProcessError(Command ['pki-server', 'cert-fix', '--ldapi-socket', '/run/slapd-IPA-TEST.socket', '--agent-uid', 'ipara', '--cert', 'sslserver', '--cert', 'ca_audit_signing', '--extra-cert', '12'] returned non-zero exit status 1: "INFO: Loading instance: pki-tomcat\nINFO: Loading global Tomcat config: /etc/tomcat/tomcat.conf\nINFO: Loading PKI Tomcat config: /usr/share/pki/etc/tomcat.conf\nINFO: Loading instance Tomcat config: /etc/pki/pki-tomcat/tomcat.conf\nINFO: Loading password config: /etc/pki/pki-tomcat/password.conf\nINFO: Loading subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Loading subsystem registry: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Loading instance registry: /etc/sysconfig/pki/tomcat/pki-tomcat/pki-tomcat\nINFO: Fixing the following system certs: ['sslserver', 'ca_audit_signing']\nINFO: Renewing the following additional certs: ['12']\nINFO: Stopping the instance to proceed with system cert renewal\nINFO: Configuring LDAP connection for CA\nINFO: Setting pkidbuser password via ldappasswd\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Selftests disabled for subsystems: ca\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Resetting password for uid=ipara,ou=people,o=ipaca\nSASL/EXTERNAL authentication started\nSASL username: gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth\nSASL SSF: 0\nINFO: Creating a temporary sslserver cert\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Trying to create a new temp cert for sslserver.\nINFO: Generate temp SSL certificate\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: CSR for sslserver has been written to /tmp/tmp58ptb9uo/sslserver.csr\nINFO: Getting signing cert info from CS.cfg\nINFO: Getting signing cert info from NSS database\nINFO: CA cert written to /tmp/tmp58ptb9uo/ca_certificate.crt\nINFO: AKI: 0x5A72C7C839FDFA5E7057273AD7D7B872B7F8419F\nINFO: Temp cert for sslserver is available at /etc/pki/pki-tomcat/certs/sslserver.crt.\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Getting sslserver cert info from CS.cfg\nINFO: Getting sslserver cert info from NSS database\nINFO: Updating CS.cfg with the new certificate\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Starting the instance\nJob for pki-tomcatd@pki-tomcat.service canceled.\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\nINFO: Selftests enabled for subsystems: ca\nINFO: Restoring LDAP connection for CA\nINFO: Storing subsystem config: /var/lib/pki/pki-tomcat/ca/conf/CS.cfg\nINFO: Storing registry config: /var/lib/pki/pki-tomcat/ca/conf/registry.cfg\n")
ipapython.admintool: ERROR: The ipa-cert-fix command failed.

Failures also observed in [testing_master_pki] Nightly PR #864 for /test_ipa_cert_fix.py::TestIpaCertFix::test_renew_expired_cert_on_master
report

PR: https://github.com/freeipa/freeipa/pull/5738

The new test has also increased total execution time which sometimes causes timeouts: http://freeipa-org-pr-ci.s3-website.eu-central-1.amazonaws.com/jobs/6d87213a-a6f3-11eb-a169-5254003b4515/runner.log.gz
@myusuf Please consider increasing timeout by 30 minutes as part of the PR

Test Failure observed in testing_master_previous PR
Report

Test Failure observed in [testing_master_pki] Nightly PR #973 , report

Failure observed in [testing_master_previous] Nightly PR #1053 , report. The reason why it's not failing every week for this run is, that this test usually times-out.

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

master:

  • 50c6359f3dfcf31983a50305f83814065643e871 ipatests: wait while http/ldap/pkinit cert get renew on replica
  • c963adc7277637c56348a83a5ced43d52b3431ee ipatests: update the timemout for test_ipa_cert_fix.py in nightlies

ipa-4-9:

  • e0aef5296b66c0b460f7e10993610fe68b312241 ipatests: test to renew certs on replica using ipa-cert-fix
  • a620e5e9e152defe144705913521c3cf556faa0e ipatests: wait while http/ldap/pkinit cert get renew on replica
  • 1b38afc0487efde57f04cf4a8c15f03be46971f3 ipatests: update the timemout for test_ipa_cert_fix.py in nightlies
  • 4a3a15f45aad016730252c09e3e173a18184603e ipatests: refactor test_ipa_cert_fix with tasks

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

Metadata