SERVER-67241 Log metrics for first ingress hello command

5 files changed, 106 insertions, 61 deletions

diff --git a/jstests/libs/session_auth_metrics_helpers.js b/jstests/libs/ingress_handshake_metrics_helpers.js
index 4d7d0dbd77c..dc1a79aff8c 100644
--- a/jstests/libs/session_auth_metrics_helpers.js
+++ b/jstests/libs/ingress_handshake_metrics_helpers.js
@@ -1,8 +1,10 @@
 "use strict";
 
+load("jstests/libs/fail_point_util.js");
 load('jstests/libs/log.js');
+load("jstests/libs/parallel_shell_helpers.js");
 
-function sessionAuthMetricsTest(conn, options) {
+function ingressHandshakeMetricsTest(conn, options) {
     // Unpack test options
 
     const {
@@ -11,7 +13,9 @@ function sessionAuthMetricsTest(conn, options) {
         dbName = 'test',
         collectionName = 'test_coll',
         preAuthDelayMillis,
-        postAuthDelayMillis
+        postAuthDelayMillis,
+        helloProcessingDelayMillis,
+        helloResponseDelayMillis,
     } = options;
 
     const totalDelayMillis = preAuthDelayMillis + postAuthDelayMillis;
@@ -29,45 +33,76 @@ function sessionAuthMetricsTest(conn, options) {
         db[collectionName].insert({foo: 42});
     }
 
-    function performTestConnection(host) {
-        let conn = new Mongo(host);
-        let db = conn.getDB(dbName);
+    function performAuthTestConnection() {
+        let testConn = new Mongo(conn.host);
+        let db = testConn.getDB(dbName);
         sleep(preAuthDelayMillis);
         db.auth(guestCredentials.user, guestCredentials.pwd);
         sleep(postAuthDelayMillis);
         db[collectionName].findOne();
     }
 
+    function performHelloTestConnection() {
+        let waitInHelloFailPoint =
+            configureFailPoint(conn, 'waitInHello', {delayMillis: helloProcessingDelayMillis});
+        let delaySendMessageFailPoint = configureFailPoint(
+            conn, 'sessionWorkflowDelaySendMessage', {millis: helloResponseDelayMillis});
+        let testConn = new Mongo(conn.host);
+        delaySendMessageFailPoint.off();
+        waitInHelloFailPoint.off();
+    }
+
     function getTotalTimeToFirstNonAuthCommandMillis() {
         let status = assert.commandWorked(conn.adminCommand({serverStatus: 1}));
+        printjson(status);
         return status.metrics.network.totalTimeToFirstNonAuthCommandMillis;
     }
 
-    function timingLogLineExists() {
+    function logLineExists(id, predicate) {
         let serverLog = assert.commandWorked(conn.adminCommand({getLog: "global"})).log;
-        for (const line of findMatchingLogLines(serverLog, {id: 6788700})) {
-            let entry = JSON.parse(line);
-            if (entry.attr.elapsedMillis >= postAuthDelayMillis) {
+        for (const line of findMatchingLogLines(serverLog, {id: id})) {
+            if (predicate(JSON.parse(line))) {
                 return true;
             }
         }
         return false;
     }
 
-    // Setup the test and return the function that will perform the test when called
-
-    setupTest();
+    function timingLogLineExists() {
+        return logLineExists(6788700, entry => entry.attr.elapsedMillis >= postAuthDelayMillis);
+    }
 
-    return function() {
-        assert.commandWorked(conn.adminCommand({clearLog: 'global'}));
+    function helloCompletedLogLineExists() {
+        return logLineExists(
+            6724100,
+            entry => (entry.attr.processingDurationMillis >= helloProcessingDelayMillis) &&
+                (entry.attr.sendingDurationMillis >= helloResponseDelayMillis) &&
+                (entry.attr.okCode == 1));
+    }
 
-        let metricBeforeTest = getTotalTimeToFirstNonAuthCommandMillis(conn);
+    function performAuthMetricsTest() {
+        let metricBeforeTest = getTotalTimeToFirstNonAuthCommandMillis();
 
-        performTestConnection(conn.host, preAuthDelayMillis, postAuthDelayMillis);
+        performAuthTestConnection();
 
-        assert(timingLogLineExists(conn, postAuthDelayMillis));
+        assert(timingLogLineExists, "No matching 'first non-auth command' log line");
 
-        let metricAfterTest = getTotalTimeToFirstNonAuthCommandMillis(conn);
+        let metricAfterTest = getTotalTimeToFirstNonAuthCommandMillis();
         assert.gte(metricAfterTest - metricBeforeTest, totalDelayMillis);
+    }
+
+    function performHelloMetricsTest() {
+        performHelloTestConnection();
+        assert(helloCompletedLogLineExists, "No matching 'hello completed' log line");
+    }
+
+    // Setup the test and return the function that will perform the test when called
+
+    setupTest();
+
+    return function() {
+        assert.commandWorked(conn.adminCommand({clearLog: 'global'}));
+        performAuthMetricsTest();
+        performHelloMetricsTest();
     };
 }
diff --git a/jstests/noPassthroughWithMongod/ingress_handshake_and_auth_metrics.js b/jstests/noPassthroughWithMongod/ingress_handshake_and_auth_metrics.js
new file mode 100644
index 00000000000..73fe4111550
--- /dev/null
+++ b/jstests/noPassthroughWithMongod/ingress_handshake_and_auth_metrics.js
@@ -0,0 +1,27 @@
+/**
+ * Tests for the ingress handshake metrics.
+ *
+ * @tags: [requires_fcv_63, featureFlagConnHealthMetrics]
+ */
+(function() {
+"use strict";
+
+load('jstests/libs/ingress_handshake_metrics_helpers.js');
+
+let rootCreds = {user: 'root', pwd: 'root'};
+let conn = MongoRunner.runMongod({auth: ''});
+
+jsTestLog("Setting up users and test data.");
+let runTest = ingressHandshakeMetricsTest(conn, {
+    preAuthDelayMillis: 50,
+    postAuthDelayMillis: 100,
+    helloProcessingDelayMillis: 50,
+    helloResponseDelayMillis: 100,
+    rootCredentials: rootCreds
+});
+
+jsTestLog("Connecting to mongod and running the test.");
+runTest();
+
+MongoRunner.stopMongod(conn, null, rootCreds);
+})();
diff --git a/jstests/noPassthroughWithMongod/session_auth_metrics.js b/jstests/noPassthroughWithMongod/session_auth_metrics.js
deleted file mode 100644
index dff71d5e3f6..00000000000
--- a/jstests/noPassthroughWithMongod/session_auth_metrics.js
+++ /dev/null
@@ -1,22 +0,0 @@
-/**
- * Tests for the connection establishment metrics.
- *
- * @tags: [requires_fcv_62, featureFlagConnHealthMetrics]
- */
-(function() {
-"use strict";
-
-load('jstests/libs/session_auth_metrics_helpers.js');
-
-let rootCreds = {user: 'root', pwd: 'root'};
-let conn = MongoRunner.runMongod({auth: ''});
-
-jsTestLog("Setting up users and test data.");
-let runTest = sessionAuthMetricsTest(
-    conn, {preAuthDelayMillis: 50, postAuthDelayMillis: 100, rootCredentials: rootCreds});
-
-jsTestLog("Connecting to mongod and running the test.");
-runTest();
-
-MongoRunner.stopMongod(conn, null, rootCreds);
-})();
diff --git a/jstests/sharding/ingress_handshake_and_auth_metrics_mongos.js b/jstests/sharding/ingress_handshake_and_auth_metrics_mongos.js
new file mode 100644
index 00000000000..bed38e6e7b2
--- /dev/null
+++ b/jstests/sharding/ingress_handshake_and_auth_metrics_mongos.js
@@ -0,0 +1,26 @@
+/**
+ * Tests for the ingress handshake metrics.
+ *
+ * @tags: [requires_fcv_63, featureFlagConnHealthMetrics]
+ */
+(function() {
+"use strict";
+
+load('jstests/libs/ingress_handshake_metrics_helpers.js');
+
+let st = new ShardingTest({shards: 0, other: {auth: ''}});
+let conn = st.s;
+
+jsTestLog("Setting up users and test data.");
+let runTest = ingressHandshakeMetricsTest(conn, {
+    preAuthDelayMillis: 50,
+    postAuthDelayMillis: 100,
+    helloProcessingDelayMillis: 50,
+    helloResponseDelayMillis: 100
+});
+
+jsTestLog("Connecting to mongos and running the test.");
+runTest();
+
+st.stop();
+})();
diff --git a/jstests/sharding/session_auth_metrics_mongos.js b/jstests/sharding/session_auth_metrics_mongos.js
deleted file mode 100644
index c6276ffbd67..00000000000
--- a/jstests/sharding/session_auth_metrics_mongos.js
+++ /dev/null
@@ -1,21 +0,0 @@
-/**
- * Tests for the connection establishment metrics.
- *
- * @tags: [requires_fcv_62, featureFlagConnHealthMetrics]
- */
-(function() {
-"use strict";
-
-load('jstests/libs/session_auth_metrics_helpers.js');
-
-let st = new ShardingTest({shards: 0, other: {auth: ''}});
-let conn = st.s;
-
-jsTestLog("Setting up users and test data.");
-let runTest = sessionAuthMetricsTest(conn, {preAuthDelayMillis: 50, postAuthDelayMillis: 100});
-
-jsTestLog("Connecting to mongos and running the test.");
-runTest();
-
-st.stop();
-})();