SERVER-84645 OCSP stapling log messages should indicate response validity (#44121)

GitOrigin-RevId: b92d8880dd30e6d0600df7bb453a52ad61cc645e

jstests/ocsp/lib/mock_ocsp.js

@@ -111,16 +111,37 @@ export class MockOCSPServer {
             args.push("--issuer_hash_algorithm=" + this.issuer_hash_algorithm);
         }
 
-        clearRawMongoProgramOutput();
+        const MAX_ATTEMPTS = 10;
+        let backoff_ms = 1000;
+        let portInUse = false;
+        for (let attempts = 0; attempts < MAX_ATTEMPTS; attempts++) {
+            clearRawMongoProgramOutput();
 
-        this.pid = _startMongoProgram({args: args});
+            const pid = _startMongoProgram({args: args});
-        assert(checkProgram(this.pid).alive);
+            assert(checkProgram(pid).alive);
 
-        assert.soon(function () {
+            portInUse = false;
-            // Change this line if the OCSP endpoint changes
+            assert.soon(function () {
-            return rawMongoProgramOutput(".*").search("Launching debugserver on port 8100") !== -1;
+                // Change this line if the OCSP endpoint changes
-        });
+                let output = rawMongoProgramOutput(".*");
+                portInUse = output.search("Address already in use") !== -1;
+                return portInUse || output.search("Running on http") !== -1;
+            });
 
+            if (!portInUse) {
+                this.pid = pid;
+                break;
+            }
+
+            assert.soon(function () {
+                return !checkProgram(pid).alive;
+            });
+            print(`Retrying OCSP mock responder startup after ${backoff_ms / 1000} seconds.`);
+            sleep(backoff_ms);
+            backoff_ms *= 2;
+        }
+
+        assert(!portInUse);
         sleep(2000);
     }
 

jstests/ocsp/ocsp_intracluster_status_logging.js

@@ -0,0 +1,134 @@
+// Tests that OCSP for intracluster TLS logs helpful error messages when verification
+// fails due to revoked peer certificates.
+// @tags: [requires_http_client, requires_ocsp_stapling]
+
+import {FAULT_REVOKED, MockOCSPServer} from "jstests/ocsp/lib/mock_ocsp.js";
+import {funWithArgs} from "jstests/libs/parallel_shell_helpers.js";
+import {
+    OCSP_CA_PEM,
+    OCSP_CLIENT_CERT,
+    OCSP_SERVER_CERT_REVOKED,
+    supportsStapling,
+    waitForServer,
+    assertClientConnectFails,
+} from "jstests/ocsp/lib/ocsp_helpers.js";
+
+if (!supportsStapling()) {
+    quit();
+}
+
+const repl_set = "ocsp-test";
+const with_stapling_options = {
+    tlsMode: "requireTLS",
+    tlsCertificateKeyFile: OCSP_SERVER_CERT_REVOKED,
+    tlsCAFile: OCSP_CA_PEM,
+    tlsAllowInvalidHostnames: "",
+    setParameter: {
+        "ocspEnabled": "true",
+    },
+    replSet: repl_set,
+    waitForConnect: false,
+};
+const no_stapling_options = Object.assign({}, with_stapling_options);
+no_stapling_options.setParameter = {
+    "ocspEnabled": "true",
+    "failpoint.disableStapling": "{'mode':'alwaysOn'}",
+};
+
+const revoked_status = {
+    "code": ErrorCodes.OCSPCertificateStatusRevoked,
+    "codeName": "OCSPCertificateStatusRevoked",
+    "errmsg": "OCSP Certificate Status: Revoked. Reason: unspecified",
+};
+
+const mock_ocsp = new MockOCSPServer(FAULT_REVOKED, 1);
+mock_ocsp.start();
+
+// Start the replica set nodes:
+// - conn1 does not staple
+// - conn2 staples revoked status,
+let conn1 = MongoRunner.runMongod(Object.assign({}, no_stapling_options));
+let conn2 = MongoRunner.runMongod(Object.assign({}, with_stapling_options));
+waitForServer(conn1);
+waitForServer(conn2);
+
+// Assert the current shell can't connect because of the revoked server certs.
+assertClientConnectFails(conn1);
+assertClientConnectFails(conn2);
+
+// In a separate shell (that ignores OCSP), initiate the replica set from conn1.
+// Expect conn1 connects to conn2; fails because conn2's stapled cert is revoked.
+async function bgValidateFunc(rs_name, ports, has_stapling_logs, expected_logid, expected_attr) {
+    function waitForLog(code, attr) {
+        assert.soon(
+            function () {
+                return checkLog.checkContainsWithAtLeastCountJson(db, code, attr, 1, "I", true);
+            },
+            `Could not find log entries containing id ${code} and attr: ${tojson(attr)}`,
+            undefined,
+            undefined,
+            {runHangAnalyzer: false},
+        );
+    }
+
+    // If this node staples, assert there are logs for both fetch/staple status AND
+    // the certificate revocation status.
+    if (has_stapling_logs) {
+        waitForLog(577163 /* OCSP fetch status */, {"status": {"code": 0}});
+        waitForLog(8464500 /* OCSP revocation status */, {
+            "status": {"code": ErrorCodes.OCSPCertificateStatusRevoked},
+        });
+    } else {
+        assert.eq(checkLog.checkContainsOnceJson(db, 577163, {}), false);
+    }
+
+    // Initiate the replica set to start egress connection to the other node.
+    assert.eq(checkLog.checkContainsOnceJson(db, expected_logid, {}), false);
+    rs.initiate({
+        _id: rs_name,
+        members: ports.map((port, idx) => {
+            return {_id: idx, host: `localhost:${port}`};
+        }),
+    });
+    waitForLog(expected_logid, expected_attr);
+}
+
+let pshell = startParallelShell(
+    funWithArgs(bgValidateFunc, repl_set, [conn1.port, conn2.port], false, 23225, {"error": revoked_status}),
+    conn1.port,
+    false,
+    "--tls",
+    "--tlsCAFile",
+    OCSP_CA_PEM,
+    "--tlsCertificateKeyFile",
+    OCSP_CLIENT_CERT,
+    "--tlsAllowInvalidHostnames",
+    "--tlsAllowInvalidCertificates",
+    "--verbose",
+    1,
+);
+pshell();
+
+// Use a parallel shell to initiate the replica set from conn2.
+// Expect conn2 connects to conn1, does OCSP on-demand status checking,
+// and fails because peer cert is revoked.
+pshell = startParallelShell(
+    funWithArgs(bgValidateFunc, repl_set, [conn1.port, conn2.port], true, 8464502, {"status": revoked_status}),
+    conn2.port,
+    false,
+    "--tls",
+    "--tlsCAFile",
+    OCSP_CA_PEM,
+    "--tlsCertificateKeyFile",
+    OCSP_CLIENT_CERT,
+    "--tlsAllowInvalidHostnames",
+    "--tlsAllowInvalidCertificates",
+    "--verbose",
+    1,
+);
+pshell();
+
+MongoRunner.stopMongod(conn1);
+MongoRunner.stopMongod(conn2);
+
+mock_ocsp.stop();

src/mongo/util/net/ssl_manager_openssl.cpp

@@ -480,8 +480,7 @@ using UniqueCertId =
 
 Status getSSLFailure(ErrorCodes::Error code, StringData errorMsg) {
     return Status(code,
-                  str::stream() << "SSL peer certificate revocation status checking failed: "
+                  str::stream() << errorMsg << " "
-                                << errorMsg << " "
                                 << SSLManagerInterface::getSSLErrorMessage(ERR_get_error()));
 }
 
@@ -526,7 +525,7 @@ StatusWith<UniqueX509> getIssuerCertForCert(SSL_CTX* context,
         storeCtx.get(), X509_LU_X509, X509_get_issuer_name(cert)));
 
     if (obj == nullptr) {
-        return getSSLFailure("Could not get X509 Object from store.");
+        return getSSLFailure("Unable to find issuer certificate from X509 store.");
     }
     return UniqueX509(X509_dup(X509_OBJECT_get0_X509(obj.get())));
 }
@@ -748,13 +747,13 @@ Future<UniqueOCSPResponse> retrieveOCSPResponse(const std::string& host,
     auto len = i2d_OCSP_REQUEST(ocspReq.get(), nullptr);
     std::vector<uint8_t> buffer;
     if (len <= 0) {
-        return getSSLFailure("Could not decode response from responder.");
+        return getSSLFailure("Failed to encode OCSP request into DER format.");
     }
 
     buffer.resize(len);
     auto bufferData = buffer.data();
     if (i2d_OCSP_REQUEST(ocspReq.get(), &bufferData) < 0) {
-        return getSSLFailure("Could not convert type OCSP Response to DER encoded object.");
+        return getSSLFailure("Failed to encode OCSP request into DER format.");
     }
 
     // Query the OCSP responder
@@ -768,7 +767,7 @@ Future<UniqueOCSPResponse> retrieveOCSPResponse(const std::string& host,
                 d2i_OCSP_RESPONSE(nullptr, &respDataPtr, responseData.size()));
 
             if (response == nullptr) {
-                return getSSLFailure("Could not retrieve OCSP Response.");
+                return getSSLFailure("Failed to decode OCSP response from DER format.");
             }
 
             return std::move(response);
@@ -865,9 +864,9 @@ StatusWith<std::pair<OCSPCertIDSet, boost::optional<Date_t>>> iterateResponse(
         auto status = OCSP_single_get0_status(singleResp, &reason, &revtime, &thisupd, &nextupd);
 
         if (status == V_OCSP_CERTSTATUS_REVOKED) {
-            return getSSLFailure(ErrorCodes::OCSPCertificateStatusRevoked,
+            return Status(ErrorCodes::OCSPCertificateStatusRevoked,
-                                 str::stream() << "OCSP Certificate Status: Revoked. Reason: "
+                          str::stream() << "OCSP Certificate Status: Revoked. Reason: "
-                                               << OCSP_crl_reason_str(reason));
+                                        << OCSP_crl_reason_str(reason));
         } else if (status != V_OCSP_CERTSTATUS_GOOD) {
             return getSSLFailure(str::stream()
                                  << "Unexpected OCSP Certificate Status. Reason: " << status);
@@ -907,29 +906,29 @@ StatusWith<std::pair<OCSPCertIDSet, boost::optional<Date_t>>> parseAndValidateOC
     X509* issuerCert,
     const OCSPCertIDSet& certIdsInRequest) {
     // Read the overall status of the OCSP response
-    int responseStatus = OCSP_response_status(response);
+    if (auto responseStatus = OCSP_response_status(response);
-    switch (responseStatus) {
+        responseStatus != OCSP_RESPONSE_STATUS_SUCCESSFUL) {
-        case OCSP_RESPONSE_STATUS_SUCCESSFUL:
+        auto& stream = str::stream() << "Failed to query the OCSP responder - ";
-            break;
+        switch (responseStatus) {
-        case OCSP_RESPONSE_STATUS_MALFORMEDREQUEST:
+            case OCSP_RESPONSE_STATUS_MALFORMEDREQUEST:
-        case OCSP_RESPONSE_STATUS_UNAUTHORIZED:
+                return getSSLFailure(stream << "Malformed request.");
-        case OCSP_RESPONSE_STATUS_SIGREQUIRED:
+            case OCSP_RESPONSE_STATUS_UNAUTHORIZED:
-            return getSSLFailure(str::stream()
+                return getSSLFailure(stream << "Unauthorized.");
-                                 << "Error querying the OCSP responder, issue with OCSP request. "
+            case OCSP_RESPONSE_STATUS_SIGREQUIRED:
-                                 << "Response Status: " << responseStatus);
+                return getSSLFailure(stream << "Signature required.");
-        case OCSP_RESPONSE_STATUS_TRYLATER:
+            case OCSP_RESPONSE_STATUS_TRYLATER:
-        case OCSP_RESPONSE_STATUS_INTERNALERROR:
+                return getSSLFailure(stream << "Received 'try later'.");
-            return getSSLFailure(str::stream()
+            case OCSP_RESPONSE_STATUS_INTERNALERROR:
-                                 << "Error querying the OCSP responder, an error occured in the "
+                return getSSLFailure(stream << "Internal error in responder.");
-                                 << "responder itself. Response Status: " << responseStatus);
+            default:
-        default:
+                return getSSLFailure(stream << "Response Status: " << responseStatus);
-            return getSSLFailure(str::stream() << "Error querying the OCSP responder. "
+        }
-                                               << "Response Status: " << responseStatus);
+        MONGO_UNREACHABLE;
     }
 
     UniqueOcspBasicResp basicResponse(OCSP_response_get1_basic(response));
     if (!basicResponse) {
-        return getSSLFailure("incomplete OCSP response.");
+        return getSSLFailure("Got incomplete OCSP response.");
     }
 
     X509_STORE* store = ca == nullptr ? SSL_CTX_get_cert_store(context) : ca;
@@ -1015,9 +1014,10 @@ Future<OCSPFetchResponse> dispatchOCSPRequests(SSL_CTX* context,
                 });
                 if (!swResponse.isOK()) {
                     if (state->finishLine.arriveWeakly()) {
-                        state->promise.setError(
+                        state->promise.setError(Status(ErrorCodes::OCSPCertificateStatusUnknown,
-                            Status(ErrorCodes::OCSPCertificateStatusUnknown,
+                                                       swResponse.getStatus().reason())
-                                   "Could not obtain status information of certificates."));
+                                                    .withContext("Failed to obtain OCSP revocation "
+                                                                 "status of server certificate."));
                     }
                     return;
                 }
@@ -1050,11 +1050,10 @@ Future<OCSPFetchResponse> dispatchOCSPRequests(SSL_CTX* context,
                     }
                 } else {
                     if (state->finishLine.arriveWeakly()) {
-                        state->promise.setError(
+                        state->promise.setError(Status(ErrorCodes::OCSPCertificateStatusUnknown,
-                            Status(ErrorCodes::OCSPCertificateStatusUnknown,
+                                                       swCertIDSetAndDuration.getStatus().reason())
-                                   swCertIDSetAndDuration.getStatus().reason())
+                                                    .withContext("Failed to obtain OCSP revocation "
-                                .withContext(
+                                                                 "status of server certificate."));
-                                    "Could not obtain status information of certificates"));
                         return;
                     }
                 }
@@ -1142,6 +1141,19 @@ boost::optional<OCSPFetchResponse> lookupOCSPForClient(const OCSPCacheKey& key)
                                            std::move(swOCSPContext.getValue()),
                                            OCSPPurpose::kClientVerify)
                           .getNoThrow();
+
+    // Assert dispatchOCSPRequests always sets a OCSPCertificateStatusUnknown status on
+    // future completion when an SSL error is encountered and it was unable to obtain
+    // a valid OCSP response.
+    dassert(swResponse.isOK() ||
+            swResponse.getStatus() == ErrorCodes::OCSPCertificateStatusUnknown);
+    LOGV2_INFO(8464501, "OCSP fetch status", "status"_attr = swResponse.getStatus());
+    if (swResponse.isOK()) {
+        LOGV2_INFO(8464502,
+                   "OCSP peer certificate revocation status",
+                   "status"_attr = swResponse.getValue().statusOfResponse);
+    }
+
     if (!swResponse.isOK() || !swResponse.getValue().cacheable()) {
         // if the response is unknown or not cacheable, (ie. because of
         // a missing nextUpdate field), then return none so that the
@@ -2003,10 +2015,9 @@ int ocspClientCallback(SSL* ssl, void* arg) {
     // CRLs or check with the OCSP responder ourselves. If it is true, then we are done.
     if (!swStapleOK.isOK()) {
         if (swStapleOK.getStatus() == ErrorCodes::OCSPCertificateStatusRevoked) {
-            LOGV2_DEBUG(23225,
+            LOGV2_INFO(23225,
-                        1,
+                       "Stapled OCSP Response validation failed",
-                        "Stapled OCSP Response validation failed",
+                       "error"_attr = swStapleOK.getStatus());
-                        "error"_attr = swStapleOK.getStatus());
             return OCSP_CLIENT_RESPONSE_NOT_ACCEPTABLE;
         }
 
@@ -2016,10 +2027,9 @@ int ocspClientCallback(SSL* ssl, void* arg) {
 
         return OCSP_CLIENT_RESPONSE_ERROR;
     } else if (!swStapleOK.getValue()) {
-        LOGV2_DEBUG(23226,
+        LOGV2_INFO(23226,
-                    1,
+                   "Stapled Certificate validation failed: Stapled response does not contain "
-                    "Stapled Certificate validation failed: Stapled response does not contain "
+                   "status information regarding the peer certificate.");
-                    "status information regarding the peer certificate.");
         return OCSP_CLIENT_RESPONSE_NOT_ACCEPTABLE;
     }
 
@@ -2317,12 +2327,12 @@ Future<Milliseconds> OCSPFetcher::fetchAndStaple(Promise<void>* promise) {
     // Generate a new verified X509StoreContext to get our own certificate chain
     UniqueX509StoreCtx storeCtx(X509_STORE_CTX_new());
     if (!storeCtx) {
-        return getSSLFailure("Could not create X509 store.");
+        return getSSLFailure("Failed to create an X509 store context.");
     }
 
     X509_STORE* store = _ca ? _ca.get() : SSL_CTX_get_cert_store(_context);
     if (X509_STORE_CTX_init(storeCtx.get(), store, NULL, NULL) == 0) {
-        return getSSLFailure("Could not initialize the X509 Store Context.");
+        return getSSLFailure("Failed to initialize the X509 store context.");
     }
 
     X509_STORE_CTX_set_cert(storeCtx.get(), _cert);
@@ -2332,7 +2342,7 @@ Future<Milliseconds> OCSPFetcher::fetchAndStaple(Promise<void>* promise) {
     X509_STORE_CTX_set_chain(storeCtx.get(), sk);
 
     if (X509_verify_cert(storeCtx.get()) <= 0) {
-        return getSSLFailure("Could not verify X509 certificate store for OCSP Stapling.");
+        return getSSLFailure("Failed to verify the configured server X509 certificate.");
     }
 
     // Extract the chain from the verified X509StoreCtx
@@ -2359,6 +2369,12 @@ Future<Milliseconds> OCSPFetcher::fetchAndStaple(Promise<void>* promise) {
                     return kOCSPUnknownStatusRefreshRate;
                 }
 
+                // Assert dispatchOCSPRequests always sets a OCSPCertificateStatusUnknown status on
+                // future completion when an SSL error is encountered and it was unable to obtain
+                // a valid OCSP response.
+                dassert(swResponse.isOK() ||
+                        swResponse.getStatus() == ErrorCodes::OCSPCertificateStatusUnknown);
+
                 // protect against pf going out of scope when asynchronous
                 if (promise != nullptr) {
                     promise->setWith([&] {
@@ -2368,7 +2384,12 @@ Future<Milliseconds> OCSPFetcher::fetchAndStaple(Promise<void>* promise) {
                     });
                 }
 
-                LOGV2_INFO(577163, "OCSP response", "status"_attr = swResponse.getStatus());
+                LOGV2_INFO(577163, "OCSP fetch status", "status"_attr = swResponse.getStatus());
+                if (swResponse.isOK()) {
+                    LOGV2_INFO(8464500,
+                               "OCSP revocation status",
+                               "status"_attr = swResponse.getValue().statusOfResponse);
+                }
                 return _manager->updateOcspStaplingContextWithResponse(std::move(swResponse));
             });
 }