diff --git a/lemur/common/celery.py b/lemur/common/celery.py index 195f8355f8..aaaf1d187c 100644 --- a/lemur/common/celery.py +++ b/lemur/common/celery.py @@ -30,12 +30,12 @@ from lemur.certificates import cli as cli_certificate from lemur.certificates import service as certificate_service from lemur.common.redis import RedisHandler -from lemur.constants import ACME_ADDITIONAL_ATTEMPTS from lemur.dns_providers import cli as cli_dns_providers from lemur.extensions import metrics from lemur.factory import create_app, json_log_formatter from lemur import fips from lemur.notifications import cli as cli_notification + from lemur.notifications.messaging import ( send_pending_failure_notification, send_reissue_no_endpoints_notification, @@ -357,27 +357,30 @@ def fetch_acme_cert(id, notify_reissue_cert_id=None): error_log = copy.deepcopy(log_data) error_log["message"] = "Pending certificate creation failure" error_log["pending_cert_id"] = pending_cert.id - error_log["last_error"] = cert.get("last_error") error_log["cn"] = pending_cert.cn - - if pending_cert.number_attempts > ACME_ADDITIONAL_ATTEMPTS: - error_log["message"] = "Deleting pending certificate" - send_pending_failure_notification( - pending_cert, notify_owner=pending_cert.notify - ) - if notify_reissue_cert_id is not None: - send_reissue_failed_notification(pending_cert) - # Mark the pending cert as resolved - pending_certificate_service.update( - cert.get("pending_cert").id, resolved=True - ) - else: - pending_certificate_service.increment_attempt(pending_cert) - pending_certificate_service.update( - cert.get("pending_cert").id, status=str(cert.get("last_error")) - ) - # Add failed pending cert task back to queue - fetch_acme_cert.delay(id, notify_reissue_cert_id) + error_log["authority"] = cert_authority.name + error_log["authority_id"] = pending_cert.authority_id + error_log["number_attempts"] = pending_cert.number_attempts + error_log["dns_provider_id"] = pending_cert.dns_provider_id + last_error = cert.get("last_error") + error_log["last_error"] = ( + str(last_error) if last_error is not None else "No error message provided by CA" + ) + # Every failed issuance consumes the CA's ACME rate limit (e.g. Let's + # Encrypt: 5 duplicate certs / failed validations per week per domain). + # Always emit the full context so rate-limit burn is attributable to a + # specific cert / domain / authority for triage. + error_log["rate_limit_relevant"] = True + + error_log["message"] = "Deleting pending certificate" + send_pending_failure_notification( + pending_cert, notify_owner=pending_cert.notify + ) + if notify_reissue_cert_id is not None: + send_reissue_failed_notification(pending_cert) + pending_certificate_service.update( + cert.get("pending_cert").id, resolved=True + ) current_app.logger.error(error_log) log_data["message"] = "Complete" log_data["new"] = new diff --git a/lemur/constants.py b/lemur/constants.py index 8b25e2f4a1..07f86cbd5e 100644 --- a/lemur/constants.py +++ b/lemur/constants.py @@ -15,9 +15,6 @@ FAILURE_METRIC_STATUS = "failure" -# when ACME attempts to resolve a certificate try in total 3 times -ACME_ADDITIONAL_ATTEMPTS = 2 - CERTIFICATE_KEY_TYPES = [ "RSA2048", "RSA4096", diff --git a/lemur/pending_certificates/cli.py b/lemur/pending_certificates/cli.py index 73b0ce2b50..9b13431327 100644 --- a/lemur/pending_certificates/cli.py +++ b/lemur/pending_certificates/cli.py @@ -12,7 +12,6 @@ from flask_script import Manager from lemur.authorities.service import get as get_authority -from lemur.constants import ACME_ADDITIONAL_ATTEMPTS from lemur.notifications.messaging import send_pending_failure_notification from lemur.pending_certificates import service as pending_certificate_service from lemur.plugins.base import plugins @@ -109,18 +108,11 @@ def fetch_all_acme(): error_log["last_error"] = cert.get("last_error") error_log["cn"] = pending_cert.cn - if pending_cert.number_attempts > ACME_ADDITIONAL_ATTEMPTS: - error_log["message"] = "Marking pending certificate as resolved" - send_pending_failure_notification( - pending_cert, notify_owner=pending_cert.notify - ) - # Mark "resolved" as True - pending_certificate_service.update(cert.id, resolved=True) - else: - pending_certificate_service.increment_attempt(pending_cert) - pending_certificate_service.update( - cert.get("pending_cert").id, status=str(cert.get("last_error")) - ) + error_log["message"] = "Marking pending certificate as resolved" + send_pending_failure_notification( + pending_cert, notify_owner=pending_cert.notify + ) + pending_certificate_service.update(cert.id, resolved=True) current_app.logger.error(error_log) log_data["message"] = "Complete" log_data["new"] = new diff --git a/lemur/plugins/lemur_acme/challenge_types.py b/lemur/plugins/lemur_acme/challenge_types.py index 1409a6f128..6e69a4a974 100644 --- a/lemur/plugins/lemur_acme/challenge_types.py +++ b/lemur/plugins/lemur_acme/challenge_types.py @@ -19,7 +19,6 @@ from sentry_sdk import capture_exception from lemur.authorizations import service as authorization_service -from lemur.constants import ACME_ADDITIONAL_ATTEMPTS from lemur.common.utils import drop_last_cert_from_chain, csr_to_string from lemur.exceptions import LemurException, InvalidConfiguration from lemur.extensions import metrics @@ -27,8 +26,6 @@ from lemur.destinations import service as destination_service from lemur.plugins.lemur_acme.acme_handlers import AcmeHandler, AcmeDnsHandler -from retrying import retry - class AcmeChallengeMissmatchError(LemurException): pass @@ -299,7 +296,6 @@ def create_certificate(self, csr, issuer_options): # TODO add external ID (if possible) return pem_certificate, pem_certificate_chain, None - @retry(stop_max_attempt_number=ACME_ADDITIONAL_ATTEMPTS, wait_fixed=5000) def create_certificate_immediately(self, acme_client, order_info, csr): try: order = acme_client.new_order(csr_to_string(csr)) diff --git a/lemur/tests/conftest.py b/lemur/tests/conftest.py index 899b91fb2b..419ed91ee2 100644 --- a/lemur/tests/conftest.py +++ b/lemur/tests/conftest.py @@ -5,7 +5,7 @@ from cryptography import x509 from cryptography.hazmat.backends import default_backend from cryptography.hazmat.primitives import hashes -from flask import current_app +from flask import current_app, g from flask_principal import identity_changed, Identity from sqlalchemy.sql import text @@ -104,6 +104,11 @@ def session(db, request): db.session.begin_nested() yield db.session db.session.rollback() + # g is app-context scoped and persists across tests. Clear request-scoped + # state so a stale, detached User from an earlier test isn't reused by a + # later test (which raises DetachedInstanceError when its attributes are + # expired). + g.pop("current_user", None) @pytest.fixture(scope="function") diff --git a/lemur/tests/test_pending_cert_no_retry.py b/lemur/tests/test_pending_cert_no_retry.py new file mode 100644 index 0000000000..621af64ff4 --- /dev/null +++ b/lemur/tests/test_pending_cert_no_retry.py @@ -0,0 +1,133 @@ +"""Tests for fetch_acme_cert no-retry + ACME rate-limit logging (EVBL-47). + +Verifies that, with retries disabled (ACME_ADDITIONAL_ATTEMPTS = 0), a pending +certificate that fails issuance is resolved immediately on the first attempt (no +re-queue), and that the failure log always carries the full ACME rate-limit +context (cn, authority, number of attempts, DNS provider, error) so rate-limit +burn is attributable for triage. +""" + +import sys +from unittest.mock import MagicMock, patch + +import pytest + +# celery.py connects to Redis at module level; pre-import it with Redis mocked so +# the @patch decorators below don't trigger a real Redis connection on first import. +if "lemur.common.celery" not in sys.modules: + with patch("redis.StrictRedis") as _mock_redis: + _mock_redis.return_value.set.return_value = True + import lemur.common.celery # noqa: F401 + +import lemur.common.celery as _celery_module # noqa: E402 + +from lemur.common.celery import fetch_acme_cert # noqa: E402 + + +@pytest.fixture(autouse=True) +def _mock_celery_current_app(monkeypatch): + """Scope the current_app mock to each test and restore the original on teardown.""" + monkeypatch.setattr(_celery_module, "current_app", MagicMock()) + + +def _pending_cert(id, number_attempts=0): + pc = MagicMock() + pc.id = id + pc.number_attempts = number_attempts + pc.resolved = False + pc.cn = "*.us3.ddbuild.io" + pc.notify = True + pc.owner = "joe@example.com" + pc.authority_id = 14 + pc.dns_provider_id = 6 + return pc + + +def _run_fetch_acme_cert(pc, last_error): + """Run fetch_acme_cert(id) with get_ordered_certificates returning a single failure. + + Returns the started mocks keyed by name so tests can assert on call behavior. + """ + plugin = MagicMock() + plugin.get_ordered_certificates.return_value = [ + {"cert": False, "pending_cert": pc, "last_error": last_error} + ] + + authority = MagicMock() + authority.name = "LetsEncryptStaging2" + authority.plugin_name = "acme-issuer" + + patchers = [ + patch( + "lemur.common.celery.pending_certificate_service.get_pending_certs", + return_value=[pc], + ), + patch("lemur.common.celery.get_authority", return_value=authority), + patch("lemur.common.celery.plugins.get", return_value=plugin), + patch("lemur.common.celery.pending_certificate_service.get", return_value=pc), + patch("lemur.common.celery.send_pending_failure_notification"), + patch("lemur.common.celery.pending_certificate_service.update"), + patch("lemur.common.celery.pending_certificate_service.increment_attempt"), + patch("lemur.common.celery.fetch_acme_cert.delay"), + ] + started = [p.start() for p in patchers] + try: + fetch_acme_cert(pc.id) + finally: + for p in patchers: + p.stop() + + return { + "get_authority": started[1], + "update": started[5], + "increment_attempt": started[6], + "delay": started[7], + } + + +def _rate_limit_error_log(mocks): + """Return the failure error_log emitted via current_app.logger.error.""" + for call in _celery_module.current_app.logger.error.call_args_list: + if call.args and isinstance(call.args[0], dict): + log = call.args[0] + if log.get("rate_limit_relevant") is True: + return log + raise AssertionError("no rate-limit-relevant error log emitted") + + +def test_fetch_acme_cert_failure_resolves_immediately_no_requeue(): + """With retries disabled, a failed pending cert is resolved on the first attempt.""" + pc = _pending_cert(1, number_attempts=0) + mocks = _run_fetch_acme_cert(pc, ValueError("Failed verification")) + + # Marked resolved + assert any( + call.kwargs.get("resolved") is True for call in mocks["update"].call_args_list + ) + # Not re-queued, not incremented + mocks["delay"].assert_not_called() + mocks["increment_attempt"].assert_not_called() + + +def test_fetch_acme_cert_failure_logs_rate_limit_context(): + """The failure log always carries the ACME rate-limit-relevant context.""" + pc = _pending_cert(1, number_attempts=0) + mocks = _run_fetch_acme_cert(pc, ValueError("Failed verification")) + + log = _rate_limit_error_log(mocks) + assert log["cn"] == pc.cn + assert log["authority"] == "LetsEncryptStaging2" + assert log["authority_id"] == pc.authority_id + assert log["number_attempts"] == pc.number_attempts + assert log["dns_provider_id"] == pc.dns_provider_id + assert log["rate_limit_relevant"] is True + assert "Failed verification" in log["last_error"] + + +def test_fetch_acme_cert_failure_logs_default_last_error_when_missing(): + """A missing last_error is logged as a meaningful default, not 'None'.""" + pc = _pending_cert(1, number_attempts=0) + mocks = _run_fetch_acme_cert(pc, None) + + log = _rate_limit_error_log(mocks) + assert log["last_error"] == "No error message provided by CA"