SERVER-68401 Log latency of requests to OCSP responder for client-side verification

2 files changed, 112 insertions, 2 deletions

diff --git a/jstests/ocsp/ocsp_client_verification_logging.js b/jstests/ocsp/ocsp_client_verification_logging.js
new file mode 100644
index 00000000000..500b5b0f582
--- /dev/null
+++ b/jstests/ocsp/ocsp_client_verification_logging.js
@@ -0,0 +1,92 @@
+// Tests that OCSP responder latency is logged for client-side verification.
+// @tags: [
+//   requires_http_client,
+//   live_record_incompatible,
+// ]
+
+load("jstests/ocsp/lib/mock_ocsp.js");
+
+(function() {
+"use strict";
+
+// We only have custom logging output for openssl.
+if (determineSSLProvider() !== "openssl") {
+    return;
+}
+
+const ocsp_options = {
+    sslMode: "requireSSL",
+    sslPEMKeyFile: OCSP_SERVER_CERT,
+    sslCAFile: OCSP_CA_PEM,
+    sslAllowInvalidHostnames: "",
+    setParameter: {
+        "failpoint.disableStapling": "{'mode':'alwaysOn'}",
+        "ocspEnabled": "true",
+    },
+};
+
+let mock_ocsp = new MockOCSPServer("", 1);
+mock_ocsp.start();
+
+let conn = MongoRunner.runMongod(ocsp_options);
+
+clearRawMongoProgramOutput();
+// The desired log line will be printed by the shell. We run a parallel shell because
+// 'rawMongoProgramOutput' will only return logs for subprocesses spawned by the shell.
+const runParallelShellSuccess = startParallelShell(
+    () => {
+        jsTestLog(
+            "Established connection with server to test successful certification verification.");
+    },
+    conn.port,
+    null /*noConnect */,
+    "--tls",
+    "--tlsCAFile",
+    OCSP_CA_PEM,
+    "--tlsCertificateKeyFile",
+    OCSP_CLIENT_CERT,
+    "--tlsAllowInvalidHostnames",
+    "--verbose",
+    1);
+
+runParallelShellSuccess();
+let output = rawMongoProgramOutput();
+assert.gte(output.search(/"id":6840101/), 0, output);
+
+mock_ocsp.stop();
+
+jsTestLog("Restarting MockOCSPServer with FAULT_REVOKED option");
+mock_ocsp = new MockOCSPServer(FAULT_REVOKED, 1);
+mock_ocsp.start();
+
+clearRawMongoProgramOutput();
+jsTestLog("Spawning parallel shell that should throw due to revoked OCSP certificate");
+assert.throws(startParallelShell(
+    () => {
+        jsTestLog("Something went wrong if we print this!");
+    },
+    conn.port,
+    null /*noConnect */,
+    "--tls",
+    "--tlsCAFile",
+    OCSP_CA_PEM,
+    "--tlsCertificateKeyFile",
+    OCSP_CLIENT_CERT,
+    "--tlsAllowInvalidHostnames",
+    "--verbose",
+    1));
+
+output = rawMongoProgramOutput();
+// Assert that the shell fails due to certificate being revoked, and we still measure OCSP responder
+// latency.
+assert.gte(output.search(/OCSPCertificateStatusRevoked/), 0);
+assert.gte(output.search(/"id":6840101/), 0);
+
+MongoRunner.stopMongod(conn);
+
+// The mongoRunner spawns a new Mongo Object to validate the collections which races
+// with the shutdown logic of the mock_ocsp responder on some platforms. We need this
+// sleep to make sure that the threads don't interfere with each other.
+sleep(1000);
+mock_ocsp.stop();
+}());
\ No newline at end of file
diff --git a/src/mongo/util/net/ssl_manager_openssl.cpp b/src/mongo/util/net/ssl_manager_openssl.cpp
index 4bcdd6055f9..c365777144b 100644
--- a/src/mongo/util/net/ssl_manager_openssl.cpp
+++ b/src/mongo/util/net/ssl_manager_openssl.cpp
@@ -1003,14 +1003,29 @@ Future<OCSPFetchResponse> dispatchOCSPRequests(SSL_CTX* context,
                                                        std::move(pf.promise),
                                                        std::move(intermediateCerts),
                                                        std::move(ocspContext));
-
+    auto startTimer = std::make_shared<Timer>();
     for (size_t i = 0; i < futureResponses.size(); i++) {
         auto futureResponse = std::move(futureResponses[i]);
         auto requestedCertIDs = requestedCertIDSets[i];
 
         std::move(futureResponse)
-            .getAsync([context, ca, state, requestedCertIDs](
+            .getAsync([context, ca, state, requestedCertIDs, startTimer, purpose](
                           StatusWith<UniqueOCSPResponse> swResponse) mutable {
+                auto requestLatency = startTimer->millis();
+                // We use a scope guard because we only want to log the metrics once we have come to
+                // a resolution on the status of the connection. This happens on the event of:
+                // 1. The first OCSP response that we get that indicates the certificate is valid or
+                //    has been revoked.
+                // 2. The last OCSP response returns and the status of the certificate is still
+                //    unknown.
+                ScopeGuard logLatencyGuard([requestLatency, purpose]() {
+                    if (purpose != OCSPPurpose::kClientVerify) {
+                        return;
+                    }
+                    LOGV2_INFO(6840101,
+                               "Completed client-side verification of OCSP request",
+                               "verificationTimeMillis"_attr = requestLatency);
+                });
                 if (!swResponse.isOK()) {
                     if (state->finishLine.arriveWeakly()) {
                         state->promise.setError(
@@ -1056,6 +1071,9 @@ Future<OCSPFetchResponse> dispatchOCSPRequests(SSL_CTX* context,
                         return;
                     }
                 }
+                // Don't log any metrics if we haven't come to a decision on the validity of the
+                // certificate yet.
+                logLatencyGuard.dismiss();
             });
     }