#8463 Nightly test failure in test_ipahealthcheck.py::TestIpaHealthCheck::test_ipa_healthcheck_expiring
Closed: fixed by abbra. Opened by frenaud.

Issue

The nightly test test_ipahealthcheck.py::TestIpaHealthCheck::test_ipa_healthcheck_expiring is sometimes failing. See for instance PR #347 with the following report and logs:

self = <ipatests.test_integration.test_ipahealthcheck.TestIpaHealthCheck object at 0x7f5f5c7a0370>
    def test_ipa_healthcheck_expiring(self):
        """
        There are two overlapping tests for expiring certs, check both.
        """
        def execute_expiring_check(check):
            """
            Test that certmonger will report warnings if expiration is near
            """
            returncode, data = run_healthcheck(
                self.master,
                "ipahealthcheck.ipa.certs",
                check,
            )
            assert returncode == 1
            assert len(data) == 12  # KRA is 12 tracked certs
            for check in data:
                if check["result"] == "SUCCESS":
                    # The CA is not expired
                    request = self.master.run_command(
                        ["getcert", "list", "-i", check["kw"]["key"]]
                    )
                    assert "caSigningCert cert-pki-ca" in request.stdout_text
                else:
                    assert check["result"] == "WARNING"
                    if check["kw"]["days"] == 21:
                        # the httpd, 389-ds and KDC renewal dates are later
                        certs = (paths.HTTPD_CERT_FILE, paths.KDC_CERT,
                                 '/etc/dirsrv/slapd-',)
                        request = self.master.run_command(
                            ["getcert", "list", "-i", check["kw"]["key"]]
                        )
                        assert any(cert in request.stdout_text
                                   for cert in certs)
                    else:
                        assert check["kw"]["days"] == 10
        # Store the current date to restore at the end of the test
        now = datetime.utcnow()
        now_str = datetime.strftime(now, "%Y-%m-%d %H:%M:%S Z")
        # Pick a cert to find the upcoming expiration
        certfile = self.master.get_file_contents(paths.RA_AGENT_PEM)
        cert = x509.load_certificate_list(certfile)
        cert_expiry = cert[0].not_valid_after
        try:
            # move date to the grace period
            self.master.run_command(['systemctl', 'stop', 'chronyd'])
            grace_date = cert_expiry - timedelta(days=10)
            grace_date = datetime.strftime(grace_date, "%Y-%m-%d 00:00:01 Z")
            self.master.run_command(['date', '-s', grace_date])
            for check in ("IPACertmongerExpirationCheck",
                          "IPACertfileExpirationCheck",):
>               execute_expiring_check(check)
test_integration/test_ipahealthcheck.py:882: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
check = {'check': 'IPACertfileExpirationCheck', 'duration': '0.829394', 'kw': {'key': '20200815094955'}, 'result': 'SUCCESS', ...}
    def execute_expiring_check(check):
        """
        Test that certmonger will report warnings if expiration is near
        """
        returncode, data = run_healthcheck(
            self.master,
            "ipahealthcheck.ipa.certs",
            check,
        )
        assert returncode == 1
        assert len(data) == 12  # KRA is 12 tracked certs
        for check in data:
            if check["result"] == "SUCCESS":
                # The CA is not expired
                request = self.master.run_command(
                    ["getcert", "list", "-i", check["kw"]["key"]]
                )
>               assert "caSigningCert cert-pki-ca" in request.stdout_text
E               assert 'caSigningCert cert-pki-ca' in "Number of certificates and requests being tracked: 12.\nRequest ID '20200815094955':\n\tstatus: POST_SAVED_CERT\n\tst...pre-save command: \n\tpost-save command: /usr/libexec/ipa/certmonger/renew_kdc_cert\n\ttrack: yes\n\tauto-renew: yes\n"
E                +  where "Number of certificates and requests being tracked: 12.\nRequest ID '20200815094955':\n\tstatus: POST_SAVED_CERT\n\tst...pre-save command: \n\tpost-save command: /usr/libexec/ipa/certmonger/renew_kdc_cert\n\ttrack: yes\n\tauto-renew: yes\n" = <pytest_multihost.transport.SSHCommand object at 0x7f5f5c26eb50>.stdout_text
test_integration/test_ipahealthcheck.py:849: AssertionError

Analysis

The test is moving the date in the future in order to show that healthcheck correctly detects the certificates that are going to expire. But as certmonger is running, certmonger starts the renewal and some certs may already be renewed when the checks are run.
The test should probably stop certmonger to make sure that the old certs are still in use when healthcheck and getcert are run.


Metadata Update from @rcritten:
- Issue assigned to rcritten

The test starts from a fresh install and moves to 10 days before expiration so theoretically all certs should still be valid (the test itself will confirm this). I agree it looks like a race condition between ipa-healthcheck and certmonger.

This could be an interesting problem since ipa-healthcheck determines its expiring dates from certmonger itself so shutting it down won't do anything, and in fact could make things worse, since on startup it refreshes all certs.

As a test this PR will shut down certmonger before time is moved: https://github.com/freeipa/freeipa/pull/5040

Upon reflection shutting down tomcat should do the trick. certmonger mail fail but ipa-healthcheck doesn't care about the status of the certmonger request (MONITORING, etc) , just the expiration date.

master:

  • 454e023ad8f0821e8a7c2400485a4d270cf4d3ea ipatests: stop the CA during healthcheck expiration test

ipa-4-8:

  • 715ec234373fc8b4aa0d00a4e9e0126522f38de1 ipatests: stop the CA during healthcheck expiration test

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

Metadata