mod_md: Log the specific reason an ACME request failed, not just "(specific information not available)".

changes-entries/70300.txt

@@ -0,0 +1,5 @@
+  *) mod_md: Log the specific reason an ACME server request failed (e.g.
+     a bad or missing CA bundle file) at error level, instead of only at
+     debug level with just a generic "Internal error (specific
+     information not available)" visible otherwise. PR 70300
+     [Arturo Bernal]

modules/md/md_curl.c

@@ -53,6 +53,36 @@ static apr_status_t curl_status(unsigned int curl_code)
     }
 }
 
+/* Whether curl_code denotes a problem with the TLS trust configuration
+ * itself (bad/missing CA bundle, cert, cipher, engine, ...) rather than a
+ * transient network condition. These are not going to be fixed by a later
+ * retry, so they are worth a log line an administrator will actually see
+ * without turning on md:trace4.
+ *
+ * CURLE_SSL_CONNECT_ERROR is deliberately excluded: libcurl uses it as a
+ * generic "something went wrong in the TLS handshake" catch-all (protocol
+ * mismatches, resets, timeouts, ...), not a reliable signal that the
+ * problem is our certificate configuration specifically. Elevating it
+ * here would mislabel transient failures as permanent and risk log
+ * flooding on retry. */
+static int curl_is_cert_error(CURLcode curl_code)
+{
+    switch (curl_code) {
+        case CURLE_SSL_ENGINE_NOTFOUND:
+        case CURLE_SSL_ENGINE_SETFAILED:
+        case CURLE_SSL_CERTPROBLEM:
+        case CURLE_SSL_CIPHER:
+        case CURLE_PEER_FAILED_VERIFICATION:
+        case CURLE_SSL_ENGINE_INITFAILED:
+        case CURLE_SSL_CACERT_BADFILE:
+        case CURLE_SSL_CRL_BADFILE:
+        case CURLE_SSL_ISSUER_ERROR:
+            return 1;
+        default:
+            return 0;
+    }
+}
+
 typedef struct {
     CURL *curl;
     CURLM *curlm;
@@ -427,8 +457,8 @@ static apr_status_t md_curl_perform(md_http_request_t *req)
 
     rv = curl_status(curle);
     if (APR_SUCCESS != rv) {
-        md_log_perror(MD_LOG_MARK, MD_LOG_DEBUG, rv, req->pool, 
-                      "request failed(%d): %s", curle, curl_easy_strerror(curle));
+        md_log_perror(MD_LOG_MARK, curl_is_cert_error(curle) ? MD_LOG_ERR : MD_LOG_DEBUG,
+                      rv, req->pool, "request failed(%d): %s", curle, curl_easy_strerror(curle));
         goto leave;
     }
 

test/modules/md/test_320_ca_cert_log_level.py

@@ -0,0 +1,110 @@
+"""mod_md's curl-based HTTP client only logged the specific reason a request
+to the ACME server failed (e.g. "Problem with the SSL CA cert (path? access
+rights?)") at debug level. At a normal production LogLevel this reason was
+invisible, and the error an administrator actually saw was the generic
+"Internal error (specific information not available)" wrapper (BZ 70300).
+
+This does not need a real ACME server: a bad MDCACertificateFile fails
+before any ACME-specific request is made, against any HTTPS endpoint.
+"""
+import datetime
+import os
+import re
+import ssl
+import threading
+from http.server import BaseHTTPRequestHandler, HTTPServer
+
+import pytest
+from cryptography import x509
+from cryptography.hazmat.primitives import hashes, serialization
+from cryptography.hazmat.primitives.asymmetric import rsa
+
+from .md_conf import MDConf
+from .md_env import MDTestEnv
+
+
+def _make_self_signed_cert(cert_path, pkey_path):
+    key = rsa.generate_private_key(public_exponent=65537, key_size=2048)
+    name = x509.Name([x509.NameAttribute(x509.NameOID.COMMON_NAME, "127.0.0.1")])
+    now = datetime.datetime.now(datetime.timezone.utc)
+    cert = (
+        x509.CertificateBuilder()
+        .subject_name(name)
+        .issuer_name(name)
+        .public_key(key.public_key())
+        .serial_number(x509.random_serial_number())
+        .not_valid_before(now - datetime.timedelta(minutes=5))
+        .not_valid_after(now + datetime.timedelta(days=1))
+        .sign(key, hashes.SHA256())
+    )
+    with open(cert_path, "wb") as f:
+        f.write(cert.public_bytes(serialization.Encoding.PEM))
+    with open(pkey_path, "wb") as f:
+        f.write(key.private_bytes(
+            encoding=serialization.Encoding.PEM,
+            format=serialization.PrivateFormat.PKCS8,
+            encryption_algorithm=serialization.NoEncryption()))
+
+
+class _DirectoryHandler(BaseHTTPRequestHandler):
+    def do_GET(self):
+        body = b'{}'
+        self.send_response(200)
+        self.send_header("Content-Type", "application/json")
+        self.send_header("Content-Length", str(len(body)))
+        self.end_headers()
+        self.wfile.write(body)
+
+    def log_message(self, *args):
+        pass
+
+
+class TestCACertLogLevel:
+
+    @pytest.fixture(scope='class')
+    def fake_acme_port(self, env):
+        cert_file = os.path.join(env.gen_dir, "md-320-fake-acme.crt")
+        pkey_file = os.path.join(env.gen_dir, "md-320-fake-acme.key")
+        _make_self_signed_cert(cert_file, pkey_file)
+
+        server = HTTPServer(("127.0.0.1", 0), _DirectoryHandler)
+        ctx = ssl.SSLContext(ssl.PROTOCOL_TLS_SERVER)
+        ctx.load_cert_chain(certfile=cert_file, keyfile=pkey_file)
+        server.socket = ctx.wrap_socket(server.socket, server_side=True)
+        port = server.server_address[1]
+        t = threading.Thread(target=server.serve_forever, daemon=True)
+        t.start()
+        yield port
+        server.shutdown()
+
+    def test_md_320_01_ca_cert_error_visible_at_warn_level(self, env, request, fake_acme_port):
+        """A bad MDCACertificateFile must be reported at a level visible
+        with a normal LogLevel, not only with md:debug/trace4."""
+        domain = env.get_request_domain(request)
+        bad_ca_file = os.path.join(env.gen_dir, "md-320-does-not-exist-ca-bundle.crt")
+        assert not os.path.exists(bad_ca_file)
+
+        conf = MDConf(env, local_ca=False)
+        conf.add([
+            "LogLevel md:warn",
+            f"MDCACertificateFile {bad_ca_file}",
+            f"MDCertificateAuthority https://127.0.0.1:{fake_acme_port}/directory",
+            "MDCertificateAgreement accepted",
+            f"MDomain {domain}",
+        ])
+        conf.add_vhost(domains=[domain], port=env.https_port, with_ssl=True)
+        conf.install()
+        assert env.apache_restart() == 0
+
+        start = env.httpd_error_log.current_pos()
+        line = env.httpd_error_log.wait_for(
+            re.compile(r'.*\[md:error\].*Problem with the SSL CA cert.*'),
+            start, timeout=15)
+        assert line, (
+            "expected the specific curl CA-cert error to be logged at "
+            "md:error, not only at md:debug/trace4")
+        env.httpd_error_log.ignore_recent(matches=[
+            r'.*Problem with the SSL CA cert.*',
+            r'.*Unsuccessful in contacting ACME server.*',
+            r'.*AH10056.*',
+        ])