diff options
-rw-r--r-- | jstests/ocsp/ocsp_client_verification_logging.js | 92 | ||||
-rw-r--r-- | src/mongo/util/net/ssl_manager_openssl.cpp | 22 |
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(); }); } |