SERVER-46026 Fix tests reliant on specific log lines

buildscripts/resmokeconfig/suites/no_passthrough.yml

@@ -10,6 +10,13 @@ selector:
   exclude_files:
   # Disable inmem_full as per SERVER-27014
   - jstests/noPassthrough/inmem_full.js
+  # Disable incompatible with json logging per SERVER-46235
+  - jstests/noPassthrough/currentop_secondary_slow_op.js
+  - jstests/noPassthrough/index_secondary_commit_after_scan_error.js
+  - jstests/noPassthrough/indexbg_killop_primary_after_init.js
+  - jstests/noPassthrough/latency_includes_lock_acquisition_time.js
+  - jstests/noPassthrough/log_and_profile_query_hash.js
+  - jstests/noPassthrough/log_format_slowms_samplerate_loglevel.js
 
 # noPassthrough tests start their own mongod's.
 executor:

jstests/noPassthrough/indexbg2.js

@@ -77,7 +77,10 @@ let failOnInsertedDuplicateValue = function(coll) {
     try {
         bgIndexBuildPid = indexBuild();
         jsTestLog("Waiting to hang before index build of i=" + duplicateKey);
-        checkLog.contains(conn, "Hanging before index build of i=" + duplicateKey);
+        checkLog.contains(
+            conn,
+            new RegExp(`(Hanging before index build of i=${
+                duplicateKey}|Hanging.*index build of i.*"where":"before","i":${duplicateKey})`));
 
         assert.commandWorked(coll.save({i: duplicateKey}));
     } finally {
@@ -106,7 +109,10 @@ let succeedWithoutWriteErrors = function(coll, newKey) {
         bgIndexBuildPid = indexBuild();
 
         jsTestLog("Waiting to hang after index build of i=" + duplicateKey);
-        checkLog.contains(conn, "Hanging after index build of i=" + duplicateKey);
+        checkLog.contains(
+            conn,
+            new RegExp(`(Hanging after index build of i=${
+                duplicateKey}|Hanging.*index build of i.*"where":"after","i":${duplicateKey})`));
 
         assert.commandWorked(coll.insert({i: duplicateKey, n: true}));
 

jstests/noPassthrough/indexbg_killop_primary_after_init.js

@@ -61,7 +61,8 @@ IndexBuildTest.waitForIndexBuildToStop(testDB);
 const exitCode = createIdx({checkExitSuccess: false});
 assert.neq(0, exitCode, 'expected shell to exit abnormally due to index build being terminated');
 
-checkLog.contains(primary, 'IndexBuildAborted: Index build aborted: ');
+checkLog.contains(
+    primary, /IndexBuildAborted: Index build aborted: |Index build aborted:.*IndexBuildAborted/);
 
 // Check that no new index has been created.  This verifies that the index build was aborted
 // rather than successfully completed.

jstests/noPassthrough/indexbg_shutdown.js

@@ -83,9 +83,11 @@ assert.commandWorked(secondDB.killOp(opId));
 // There should be a message for each index we tried to create.
 checkLog.containsWithCount(
     replTest.getSecondary(),
-    'index build: starting on ' + masterColl.getFullName() + ' properties: { v: 2, key: { i:',
+    new RegExp(`(index build: starting on ${
+        masterColl
+            .getFullName()} properties: \\{ v: 2, key: \\{ i:|index build: starting on .*"ns":"${
+        masterColl.getFullName()}".*"descriptor":"\\{ v: 2, key: \\{ i)`),
     indexSpecs.length);
-
 jsTest.log("Restarting secondary to retry replication");
 
 // Secondary should restart cleanly.
@@ -100,7 +102,10 @@ replTest.restart(secondaryId, {}, /*wait=*/true);
 // the message was logged twice in total.
 checkLog.containsWithCount(
     replTest.getSecondary(),
-    'index build: starting on ' + masterColl.getFullName() + ' properties: { v: 2, key: { i:',
+    new RegExp(`(index build: starting on ${
+        masterColl
+            .getFullName()} properties: \\{ v: 2, key: \\{ i:|index build: starting on .*"ns":"${
+        masterColl.getFullName()}".*"descriptor":"\\{ v: 2, key: \\{ i)`),
     indexSpecs.length);
 
 replTest.stopSet();

jstests/noPassthrough/log_find_getmore.js

@@ -3,6 +3,8 @@
  * Legacy operations should be upconverted to match the format of their command counterparts.
  * @tags: [requires_profiling]
  */
+load("jstests/libs/logv2_helpers.js");
+
 (function() {
 "use strict";
 
@@ -62,6 +64,10 @@ let logLine =
     'command log_getmore.test appName: "MongoDB Shell" command: find { find: "test", filter:' +
     ' { a: { $gt: 0.0 } }, skip: 1.0, batchSize: 5.0, limit: 10.0, singleBatch: false, sort:' +
     ' { a: 1.0 }, hint: { a: 1.0 }';
+if (isJsonLog(conn)) {
+    logLine =
+        '"msg":"slow query","attr":{"type":"command","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"find":"test","filter":{"a":{"$gt":0.0}},"skip":1.0,"batchSize":5.0,"limit":10.0,"singleBatch":false,"sort":{"a":1.0},"hint":{"a":1.0}';
+}
 
 // Check the logs to verify that find appears as above.
 assertLogLineContains(conn, logLine);
@@ -90,6 +96,14 @@ logLine = [
         'false, sort: { a: 1.0 }, hint: { a: 1.0 }'
 ];
 
+if (isJsonLog(conn)) {
+    logLine = [
+        `"msg":"slow query","attr":{"type":"command","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"getMore":${
+            cursorIdToString(cursorid)},"collection":"test","batchSize":5.0,`,
+        '"originatingCommand":{"find":"test","filter":{"a":{"$gt":0.0}},"skip":1.0,"batchSize":5.0,"limit":10.0,"singleBatch":false,"sort":{"a":1.0},"hint":{"a":1.0}'
+    ];
+}
+
 assertLogLineContains(conn, logLine);
 
 // TEST: Verify the log format of a getMore command following an aggregation.
@@ -105,6 +119,14 @@ logLine = [
         '[ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 }'
 ];
 
+if (isJsonLog(conn)) {
+    logLine = [
+        `"msg":"slow query","attr":{"type":"command","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"getMore":${
+            cursorIdToString(cursorid)},"collection":"test"`,
+        '"originatingCommand":{"aggregate":"test","pipeline":[{"$match":{"a":{"$gt":0.0}}}],"cursor":{"batchSize":0.0},"hint":{"a":1.0}'
+    ];
+}
+
 assertLogLineContains(conn, logLine);
 
 //
@@ -122,6 +144,11 @@ cursorid = getLatestProfilerEntry(testDB).cursorid;
 logLine = 'query log_getmore.test appName: "MongoDB Shell" command: { find: "test", filter: { a: ' +
     '{ $gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 }';
 
+if (isJsonLog(conn)) {
+    logLine =
+        '"msg":"slow query","attr":{"type":"query","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"find":"test","filter":{"a":{"$gt":0.0}},"skip":1,"ntoreturn":5,"sort":{"a":1.0},"hint":{"a":1.0}}';
+}
+
 assertLogLineContains(conn, logLine);
 
 // TEST: Verify that a query whose filter contains a field named 'query' appears as expected in
@@ -133,6 +160,11 @@ logLine =
     'query log_getmore.test appName: "MongoDB Shell" command: { find: "test", filter: { query:' +
     ' "foo" } }';
 
+if (isJsonLog(conn)) {
+    logLine =
+        '"msg":"slow query","attr":{"type":"query","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"find":"test","filter":{"query":"foo"}}';
+}
+
 assertLogLineContains(conn, logLine);
 
 // TEST: Verify that a legacy getMore following a find is logged in the expected format. This
@@ -146,6 +178,10 @@ logLine = 'getmore log_getmore.test appName: "MongoDB Shell" command: { getMore:
     ', collection: "test", batchSize: 5 } originatingCommand: { find: "test", filter: { a: {' +
     ' $gt: 0.0 } }, skip: 1, ntoreturn: 5, sort: { a: 1.0 }, hint: { a: 1.0 }';
 
+if (isJsonLog(conn)) {
+    logLine = `"msg":"slow query","attr":{"type":"getmore","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"getMore":${cursorIdToString(cursorid)},"collection":"test","batchSize":5},"originatingCommand":{"find":"test","filter":{"a":{"$gt":0.0}},"skip":1,"ntoreturn":5,"sort":{"a":1.0},"hint":{"a":1.0}}`;
+}
+
 assertLogLineContains(conn, logLine);
 
 // TEST: Verify that a legacy getMore following an aggregation is logged in the expected format.
@@ -163,6 +199,14 @@ logLine = [
         ' [ { $match: { a: { $gt: 0.0 } } } ], cursor: { batchSize: 0.0 }, hint: { a: 1.0 }'
 ];
 
+if (isJsonLog(conn)) {
+    logLine = [
+        `"msg":"slow query","attr":{"type":"getmore","ns":"log_getmore.test","appName":"MongoDB Shell","command":{"getMore":${
+            cursorIdToString(cursorid)},"collection":"test","batchSize":0}`,
+        '"originatingCommand":{"aggregate":"test","pipeline":[{"$match":{"a":{"$gt":0.0}}}],"cursor":{"batchSize":0.0},"hint":{"a":1.0}'
+    ];
+}
+
 assertLogLineContains(conn, logLine);
 MongoRunner.stopMongod(conn);
 })();

jstests/noPassthrough/parse_zone_info.js

@@ -3,7 +3,7 @@
 // Test that a bad file causes startup to fail.
 let conn = MongoRunner.runMongod({timeZoneInfo: "jstests/libs/config_files/bad_timezone_info"});
 assert.eq(conn, null, "expected launching mongod with bad timezone rules to fail");
-assert.neq(-1, rawMongoProgramOutput().indexOf("Fatal assertion 40475"));
+assert.neq(-1, rawMongoProgramOutput().search(/Fatal assertion.*40475/));
 
 // Test that a non-existent directory causes startup to fail.
 conn = MongoRunner.runMongod({timeZoneInfo: "jstests/libs/config_files/missing_directory"});

jstests/noPassthrough/port_options.js

@@ -19,10 +19,11 @@ function runTest(bindIP, expectOk) {
         // We use assert.soonNoExcept() here because the mongod may not be logging yet.
         assert.soonNoExcept(() => {
             const logContents = rawMongoProgramOutput();
-            const found = logContents.match(/waiting for connections on port (\d+)/);
+            const found =
+                logContents.match(/waiting for connections on port( (\d+)|.*listenerPort":(\d+))/);
             if (found !== null) {
                 print("Found message from mongod with port it is listening on: " + found[0]);
-                port = found[1];
+                port = found[2] != undefined ? found[2] : found[3];
                 return true;
             }
         });

jstests/sharding/time_zone_info_mongos.js

@@ -23,7 +23,7 @@ assert.eq(mongosCfg.parsed.processManagement.timeZoneInfo, tzGoodInfo);
 // Test that a bad timezone file causes mongoS startup to fail.
 let conn = MongoRunner.runMongos({configdb: st.configRS.getURL(), timeZoneInfo: tzBadInfo});
 assert.eq(conn, null, "expected launching mongos with bad timezone rules to fail");
-assert.neq(-1, rawMongoProgramOutput().search(/Fatal assertion.*40475/) != -1);
+assert.neq(-1, rawMongoProgramOutput().search(/Fatal assertion.*40475/));
 
 // Test that a non-existent timezone directory causes mongoS startup to fail.
 conn = MongoRunner.runMongos({configdb: st.configRS.getURL(), timeZoneInfo: tzNoInfo});
@@ -96,4 +96,4 @@ timeZonePipeline = buildTimeZonePipeline("Europe/Dublin");
 assert.eq(assert.throws(() => mongosColl.aggregate(timeZonePipeline)).code, 40485);
 
 st.stop();
-})();
+})();