SERVER-46026 Fix initial_sync_drop_against_last_stable.js with JSON logs

4 files changed, 75 insertions, 15 deletions

diff --git a/jstests/libs/kill_sessions.js b/jstests/libs/kill_sessions.js
index bf4a2c541b8..c05dae370a6 100644
--- a/jstests/libs/kill_sessions.js
+++ b/jstests/libs/kill_sessions.js
@@ -250,7 +250,7 @@ var _kill_sessions_api_module = (function() {
         for (let hostToCheck of hostsToCheck) {
             if (hostToCheck.host in this._cursors) {
                 if (isJsonLog(hostToCheck)) {
-                    assert(checkLog.checkContainsOnceJson(
+                    assert(checkLog.checkContainsOnceJsonStringMatch(
                                hostToCheck,
                                20528,
                                'id',
diff --git a/jstests/multiVersion/initial_sync_drop_against_last_stable.js b/jstests/multiVersion/initial_sync_drop_against_last_stable.js
index e36a2a8606e..bcccaa96fef 100644
--- a/jstests/multiVersion/initial_sync_drop_against_last_stable.js
+++ b/jstests/multiVersion/initial_sync_drop_against_last_stable.js
@@ -78,7 +78,7 @@ function setupTest({failPoint, extraFailPointData, secondaryStartupParams}) {
     replTest.waitForState(secondary, ReplSetTest.State.STARTUP_2);
 }
 
-function finishTest({failPoint, expectedLog, waitForDrop, createNew}) {
+function finishTest({failPoint, expectedLog, expectedLogId, waitForDrop, createNew}) {
     // Get the uuid for use in checking the log line.
     let uuid = getUUIDFromListCollections(primaryDB, collName);
 
@@ -99,13 +99,24 @@ function finishTest({failPoint, expectedLog, waitForDrop, createNew}) {
     jsTestLog("Allowing secondary to continue.");
     assert.commandWorked(secondary.adminCommand({configureFailPoint: failPoint, mode: 'off'}));
 
-    if (expectedLog) {
-        expectedLog = eval(expectedLog);
-        if (isJsonLog(primaryColl.getMongo())) {
-            expectedLog = expectedLog.replace(/"/g, "\\\"");
+    if (isJsonLog(primaryColl.getMongo())) {
+        if (expectedLogId) {
+            let attrValues = {
+                "ns": nss,
+                "uuid": function(attr) {
+                    return BinData(parseInt(attr.uuid.$binary.subType), attr.uuid.$binary.base64)
+                               .toString() === uuid.toString();
+                }
+            };
+
+            checkLog.containsJson(secondary, expectedLogId, attrValues);
+        }
+    } else {
+        if (expectedLog) {
+            expectedLog = eval(expectedLog);
+            jsTestLog(expectedLog);
+            checkLog.contains(secondary, expectedLog);
         }
-        jsTestLog(expectedLog);
-        checkLog.contains(secondary, expectedLog);
     }
 
     jsTestLog("Waiting for initial sync to complete.");
@@ -148,6 +159,7 @@ runDropTest({
     failPoint: "initialSyncHangCollectionClonerAfterHandlingBatchResponse",
     secondaryStartupParams: {collectionClonerBatchSize: 1},
     waitForDrop: true,
+    expectedLogId: 21132,
     expectedLog:
         "`CollectionCloner ns: '${nss}' uuid: ${uuid} stopped because collection was dropped on source.`"
 });
@@ -158,6 +170,7 @@ runDropTest({
     failPoint: "initialSyncHangCollectionClonerAfterHandlingBatchResponse",
     secondaryStartupParams: {collectionClonerBatchSize: 1},
     waitForDrop: true,
+    expectedLogId: 21132,
     expectedLog:
         "`CollectionCloner ns: '${nss}' uuid: ${uuid} stopped because collection was dropped on source.`",
     createNew: true
diff --git a/src/mongo/db/repl/collection_cloner.cpp b/src/mongo/db/repl/collection_cloner.cpp
index 8ad5135f5eb..43e7630e6b0 100644
--- a/src/mongo/db/repl/collection_cloner.cpp
+++ b/src/mongo/db/repl/collection_cloner.cpp
@@ -118,12 +118,11 @@ BaseCloner::AfterStageBehavior CollectionCloner::CollectionClonerStage::run() {
     try {
         return ClonerStage<CollectionCloner>::run();
     } catch (const ExceptionFor<ErrorCodes::NamespaceNotFound>&) {
-        LOGV2(
-            21132,
-            "CollectionCloner ns: '{getCloner_getSourceNss}' uuid: "
-            "UUID(\"{getCloner_getSourceUuid}\") stopped because collection was dropped on source.",
-            "getCloner_getSourceNss"_attr = getCloner()->getSourceNss(),
-            "getCloner_getSourceUuid"_attr = getCloner()->getSourceUuid());
+        LOGV2(21132,
+              "CollectionCloner ns: '{ns}' uuid: "
+              "UUID(\"{uuid}\") stopped because collection was dropped on source.",
+              "ns"_attr = getCloner()->getSourceNss(),
+              "uuid"_attr = getCloner()->getSourceUuid());
         getCloner()->waitForDatabaseWorkToComplete();
         return kSkipRemainingStages;
     } catch (const DBException&) {
diff --git a/src/mongo/shell/check_log.js b/src/mongo/shell/check_log.js
index db9e830219f..2f5758b47e5 100644
--- a/src/mongo/shell/check_log.js
+++ b/src/mongo/shell/check_log.js
@@ -50,13 +50,46 @@ checkLog = (function() {
         return false;
     };
 
+    const checkContainsOnceJson = function(conn, id, attrsDict) {
+        const logMessages = getGlobalLog(conn);
+        if (logMessages === null) {
+            return false;
+        }
+
+        for (let logMsg of logMessages) {
+            const obj = JSON.parse(logMsg);
+            if (obj.id === id) {
+                let allAttrMatch = true;
+                for (let attrKey in attrsDict) {
+                    const attrValue = attrsDict[attrKey];
+                    if (attrValue instanceof Function) {
+                        if (!attrValue(obj.attr[attrKey])) {
+                            allAttrMatch = false;
+                            break;
+                        }
+                    } else {
+                        if (obj.attr[attrKey] !== attrValue) {
+                            allAttrMatch = false;
+                            break;
+                        }
+                    }
+                }
+                if (allAttrMatch) {
+                    return true;
+                }
+            }
+        }
+
+        return false;
+    };
+
     /*
      * Calls the 'getLog' function on the provided connection 'conn' to see if a log with the
      * provided id is found in the logs. If the id is found it looks up the specified attrribute by
      * attrName and checks if the msg is found in its value. Note: this function does not throw an
      * exception, so the return value should not be ignored.
      */
-    const checkContainsOnceJson = function(conn, id, attrName, msg) {
+    const checkContainsOnceJsonStringMatch = function(conn, id, attrName, msg) {
         const logMessages = getGlobalLog(conn);
         if (logMessages === null) {
             return false;
@@ -86,6 +119,19 @@ checkLog = (function() {
         });
     };
 
+    let containsJson = function(conn, id, attrsDict, timeout = 5 * 60 * 1000) {
+        // Don't run the hang analyzer because we don't expect contains() to always succeed.
+        assert.soon(
+            function() {
+                return checkContainsOnceJson(conn, id, attrsDict);
+            },
+            'Could not find log entries containing the following id: ' + id +
+                ', and attrs: ' + attrsDict,
+            timeout,
+            300,
+            {runHangAnalyzer: false});
+    };
+
     /*
      * Calls the 'getLog' function at regular intervals on the provided connection 'conn' until
      * the provided 'msg' is found in the logs 'expectedCount' times, or it times out.
@@ -193,7 +239,9 @@ checkLog = (function() {
         getGlobalLog: getGlobalLog,
         checkContainsOnce: checkContainsOnce,
         checkContainsOnceJson: checkContainsOnceJson,
+        checkContainsOnceJsonStringMatch: checkContainsOnceJsonStringMatch,
         contains: contains,
+        containsJson: containsJson,
         containsWithCount: containsWithCount,
         containsWithAtLeastCount: containsWithAtLeastCount,
         formatAsLogLine: formatAsLogLine,