diff options
-rw-r--r-- | jstests/libs/check_log.js | 53 | ||||
-rw-r--r-- | jstests/noPassthroughWithMongod/initial_sync_oplog_rollover.js | 17 | ||||
-rw-r--r-- | jstests/noPassthroughWithMongod/initial_sync_replSetGetStatus.js | 20 | ||||
-rw-r--r-- | jstests/replsets/disallow_adding_initialized_node1.js | 15 | ||||
-rw-r--r-- | jstests/replsets/disallow_adding_initialized_node2.js | 17 | ||||
-rw-r--r-- | jstests/replsets/double_rollback.js | 19 | ||||
-rw-r--r-- | jstests/replsets/initial_sync_applier_error.js | 20 | ||||
-rw-r--r-- | jstests/replsets/initial_sync_update_missing_doc1.js | 29 | ||||
-rw-r--r-- | jstests/replsets/initial_sync_update_missing_doc2.js | 28 | ||||
-rw-r--r-- | jstests/replsets/read_after_optime.js | 29 | ||||
-rw-r--r-- | jstests/sharding/config_version_rollback.js | 20 |
11 files changed, 106 insertions, 161 deletions
diff --git a/jstests/libs/check_log.js b/jstests/libs/check_log.js new file mode 100644 index 00000000000..8cb064f9558 --- /dev/null +++ b/jstests/libs/check_log.js @@ -0,0 +1,53 @@ +"use strict"; + +/* + * Helper functions which connect to a server, and check its logs for particular strings. + */ +var checkLog = (function() { + /* + * Calls the 'getLog' function at regular intervals on the provided connection 'conn' until the + * provided 'msg' is found in the logs, or 5 minutes have elapsed. Throws an exception on + * timeout. + */ + var contains = function(conn, msg) { + assert.soon( + function() { + var logMessages = assert.commandWorked(conn.adminCommand({getLog: 'global'})).log; + for (var i = 0; i < logMessages.length; i++) { + if (logMessages[i].indexOf(msg) != -1) { + return true; + } + } + return false; + }, + 'Could not find log entries containing the following message: ' + msg, + 5 * 60 * 1000, + 300); + }; + + /* + * Calls the 'getLog' function at regular intervals on the provided connection 'conn' until the + * provided 'msg' is found in the logs exactly 'expectedCount' times, or 5 minutes have elapsed. + * Throws an exception on timeout. + */ + var containsWithCount = function(conn, msg, expectedCount) { + var count = 0; + assert.soon( + function() { + var logMessages = assert.commandWorked(conn.adminCommand({getLog: 'global'})).log; + for (var i = 0; i < logMessages.length; i++) { + if (logMessages[i].indexOf(msg) != -1) { + count++; + } + } + + return expectedCount === count; + }, + 'Expected ' + expectedCount + ', but instead saw ' + count + + ' log entries containing the following message: ' + msg, + 5 * 60 * 1000, + 300); + }; + + return {contains: contains, containsWithCount: containsWithCount}; +})(); diff --git a/jstests/noPassthroughWithMongod/initial_sync_oplog_rollover.js b/jstests/noPassthroughWithMongod/initial_sync_oplog_rollover.js index 9b6f6a7477d..3a47e14447c 100644 --- a/jstests/noPassthroughWithMongod/initial_sync_oplog_rollover.js +++ b/jstests/noPassthroughWithMongod/initial_sync_oplog_rollover.js @@ -9,6 +9,8 @@ (function() { "use strict"; + load("jstests/libs/check_log.js"); + // If the parameter is already set, don't run this test. var parameters = db.adminCommand({getCmdLineOpts: 1}).parsed.setParameter; if (parameters.use3dot2InitialSync || parameters.initialSyncOplogBuffer) { @@ -46,19 +48,8 @@ {configureFailPoint: 'initialSyncHangBeforeCopyingDatabases', mode: 'alwaysOn'})); replSet.reInitiate(); - // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg); - }; - checkLog(secondary, 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); + checkLog.contains(secondary, + 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); // Keep inserting large documents until they roll over the oplog. const largeStr = new Array(4 * 1024 * oplogSizeOnPrimary).join('aaaaaaaa'); diff --git a/jstests/noPassthroughWithMongod/initial_sync_replSetGetStatus.js b/jstests/noPassthroughWithMongod/initial_sync_replSetGetStatus.js index 2ad77904ad4..0c9610e9ad6 100644 --- a/jstests/noPassthroughWithMongod/initial_sync_replSetGetStatus.js +++ b/jstests/noPassthroughWithMongod/initial_sync_replSetGetStatus.js @@ -5,6 +5,8 @@ (function() { "use strict"; + load("jstests/libs/check_log.js"); + // If the parameter is already set, don't run this test. var parameters = db.adminCommand({getCmdLineOpts: 1}).parsed.setParameter; if (parameters.use3dot2InitialSync || parameters.initialSyncOplogBuffer) { @@ -38,21 +40,9 @@ {configureFailPoint: 'initialSyncHangBeforeFinish', mode: 'alwaysOn'})); replSet.reInitiate(); - // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 10000, 1000); - }; - // Wait for initial sync to pause before it copies the databases. - checkLog(secondary, 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); + checkLog.contains(secondary, + 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); // Test that replSetGetStatus returns the correct results while initial sync is in progress. var res = assert.commandWorked(secondary.adminCommand({replSetGetStatus: 1})); @@ -74,7 +64,7 @@ {configureFailPoint: 'initialSyncHangBeforeCopyingDatabases', mode: 'off'})); // Wait for initial sync to pause right before it finishes. - checkLog(secondary, 'initial sync - initialSyncHangBeforeFinish fail point enabled'); + checkLog.contains(secondary, 'initial sync - initialSyncHangBeforeFinish fail point enabled'); // Test that replSetGetStatus returns the correct results when initial sync is at the very end. res = assert.commandWorked(secondary.adminCommand({replSetGetStatus: 1, initialSync: 1})); diff --git a/jstests/replsets/disallow_adding_initialized_node1.js b/jstests/replsets/disallow_adding_initialized_node1.js index e641e89bc28..910e71c7d8c 100644 --- a/jstests/replsets/disallow_adding_initialized_node1.js +++ b/jstests/replsets/disallow_adding_initialized_node1.js @@ -3,8 +3,10 @@ // Initialize two replica sets A and B with the same name: A_0; B_0 // Add B_0 to the replica set A. This operation should fail on replica set A should fail on // detecting an inconsistent replica set ID in the heartbeat response metadata from B_0. + (function() { 'use strict'; + load("jstests/libs/check_log.js"); var name = 'disallow_adding_initialized_node1'; var replSetA = new ReplSetTest({ @@ -55,20 +57,9 @@ assert.eq(primaryB, newPrimaryB); // Mismatch replica set IDs in heartbeat responses should be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 60000, 1000); - }; var msgB = "replica set IDs do not match, ours: " + configB.settings.replicaSetId + "; remote node's: " + configA.settings.replicaSetId; - checkLog(primaryB, msgB); + checkLog.contains(primaryB, msgB); var statusA = assert.commandWorked(primaryA.adminCommand({replSetGetStatus: 1})); var statusB = assert.commandWorked(primaryB.adminCommand({replSetGetStatus: 1})); diff --git a/jstests/replsets/disallow_adding_initialized_node2.js b/jstests/replsets/disallow_adding_initialized_node2.js index 14e53bf3208..e92fc77880b 100644 --- a/jstests/replsets/disallow_adding_initialized_node2.js +++ b/jstests/replsets/disallow_adding_initialized_node2.js @@ -8,8 +8,10 @@ // This test requires users to persist across a restart. // @tags: [requires_persistence] + (function() { 'use strict'; + load("jstests/libs/check_log.js"); var name = 'disallow_adding_initialized_node2'; var replSetA = new ReplSetTest({ @@ -62,23 +64,12 @@ assert.eq(primaryB, newPrimaryB); // Mismatch replica set IDs in heartbeat responses should be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 60000, 1000); - }; var msgA = "replica set IDs do not match, ours: " + configA.settings.replicaSetId + "; remote node's: " + configB.settings.replicaSetId; var msgB = "replica set IDs do not match, ours: " + configB.settings.replicaSetId + "; remote node's: " + configA.settings.replicaSetId; - checkLog(primaryA, msgA); - checkLog(primaryB, msgB); + checkLog.contains(primaryA, msgA); + checkLog.contains(primaryB, msgB); var statusA = assert.commandWorked(primaryA.adminCommand({replSetGetStatus: 1})); var statusB = assert.commandWorked(primaryB.adminCommand({replSetGetStatus: 1})); diff --git a/jstests/replsets/double_rollback.js b/jstests/replsets/double_rollback.js index da655d2b7e2..2c3200662a7 100644 --- a/jstests/replsets/double_rollback.js +++ b/jstests/replsets/double_rollback.js @@ -9,8 +9,10 @@ * it rolled back, which could then lead to a double-rollback when node 2 was reconnected * to node 1 and tried to apply its oplog despite not being in a consistent state. */ + (function() { 'use strict'; + load("jstests/libs/check_log.js"); var name = "double_rollback"; var dbName = "test"; @@ -97,18 +99,7 @@ jsTestLog("Wait for failpoint on node 2 to pause rollback before it finishes"); // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg); - }; - checkLog(nodes[2], 'rollback - rollbackHangBeforeFinish fail point enabled'); + checkLog.contains(nodes[2], 'rollback - rollbackHangBeforeFinish fail point enabled'); jsTestLog("Repartition to: [1,3,4] and [0,2]."); nodes[2].disconnect(nodes[1]); @@ -125,8 +116,8 @@ // for a sync source it can use to reach minvalid and get back into SECONDARY state. Node 0 // is the only node it can reach, but since node 0 doesn't contain node 2's minvalid oplog entry // node 2 will refuse to use it as a sync source. - checkLog(nodes[2], - "remote oplog does not contain entry with optime matching our required optime"); + checkLog.contains( + nodes[2], "remote oplog does not contain entry with optime matching our required optime"); var node0RBID = nodes[0].adminCommand('replSetGetRBID').rbid; var node1RBID = nodes[1].adminCommand('replSetGetRBID').rbid; diff --git a/jstests/replsets/initial_sync_applier_error.js b/jstests/replsets/initial_sync_applier_error.js index 0bd98a82e7f..543e26d49b7 100644 --- a/jstests/replsets/initial_sync_applier_error.js +++ b/jstests/replsets/initial_sync_applier_error.js @@ -11,6 +11,8 @@ (function() { "use strict"; + load("jstests/libs/check_log.js"); + var parameters = TestData.setParameters; if (parameters && parameters.indexOf("use3dot2InitialSync=true") != -1) { jsTest.log("Skipping this test because use3dot2InitialSync was provided."); @@ -40,26 +42,16 @@ replSet.reInitiate(); // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 60000, 1000); - }; - checkLog(secondary, 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); + checkLog.contains(secondary, + 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); var newCollName = name + '_2'; assert.commandWorked(coll.renameCollection(newCollName, true)); assert.commandWorked(secondary.getDB('admin').runCommand( {configureFailPoint: 'initialSyncHangBeforeCopyingDatabases', mode: 'off'})); - checkLog(secondary, 'Applying renameCollection not supported'); - checkLog(secondary, 'initial sync done'); + checkLog.contains(secondary, 'Applying renameCollection not supported'); + checkLog.contains(secondary, 'initial sync done'); replSet.awaitReplication(); replSet.awaitSecondaryNodes(); diff --git a/jstests/replsets/initial_sync_update_missing_doc1.js b/jstests/replsets/initial_sync_update_missing_doc1.js index 56591d1cc8b..d2d3c6aed58 100644 --- a/jstests/replsets/initial_sync_update_missing_doc1.js +++ b/jstests/replsets/initial_sync_update_missing_doc1.js @@ -11,6 +11,8 @@ */ (function() { + load("jstests/libs/check_log.js"); + var parameters = TestData.setParameters; if (parameters && parameters.indexOf("use3dot2InitialSync=true") != -1) { jsTest.log("Skipping this test because use3dot2InitialSync was provided."); @@ -42,18 +44,8 @@ replSet.reInitiate(); // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 60000, 1000); - }; - checkLog(secondary, 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); + checkLog.contains(secondary, + 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); assert.writeOK(coll.update({_id: 0}, {x: 2}, {upsert: false, writeConcern: {w: 1}})); assert.writeOK(coll.remove({_id: 0}, {justOne: true, writeConcern: {w: 1}})); @@ -61,10 +53,10 @@ assert.commandWorked(secondary.getDB('admin').runCommand( {configureFailPoint: 'initialSyncHangBeforeCopyingDatabases', mode: 'off'})); - checkLog(secondary, 'update of non-mod failed'); - checkLog(secondary, 'adding missing object'); - checkLog(secondary, - 'initial sync - initialSyncHangBeforeGettingMissingDocument fail point enabled'); + checkLog.contains(secondary, 'update of non-mod failed'); + checkLog.contains(secondary, 'adding missing object'); + checkLog.contains( + secondary, 'initial sync - initialSyncHangBeforeGettingMissingDocument fail point enabled'); var res = assert.commandWorked(secondary.adminCommand({replSetGetStatus: 1, initialSync: 1})); assert.eq(res.initialSyncStatus.fetchedMissingDocs, 0); @@ -75,8 +67,9 @@ assert.commandWorked(secondary.getDB('admin').runCommand( {configureFailPoint: 'initialSyncHangBeforeGettingMissingDocument', mode: 'off'})); - checkLog(secondary, 'missing object not found on source. presumably deleted later in oplog'); - checkLog(secondary, 'initial sync done'); + checkLog.contains(secondary, + 'missing object not found on source. presumably deleted later in oplog'); + checkLog.contains(secondary, 'initial sync done'); replSet.awaitReplication(); replSet.awaitSecondaryNodes(); diff --git a/jstests/replsets/initial_sync_update_missing_doc2.js b/jstests/replsets/initial_sync_update_missing_doc2.js index c88715bd9ec..9418757468c 100644 --- a/jstests/replsets/initial_sync_update_missing_doc2.js +++ b/jstests/replsets/initial_sync_update_missing_doc2.js @@ -11,6 +11,8 @@ */ (function() { + load("jstests/libs/check_log.js"); + var parameters = TestData.setParameters; if (parameters && parameters.indexOf("use3dot2InitialSync=true") != -1) { jsTest.log("Skipping this test because use3dot2InitialSync was provided."); @@ -42,18 +44,8 @@ replSet.reInitiate(); // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon(function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, 'Did not see a log entry containing the following message: ' + msg, 60000, 1000); - }; - checkLog(secondary, 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); + checkLog.contains(secondary, + 'initial sync - initialSyncHangBeforeCopyingDatabases fail point enabled'); assert.writeOK(coll.update({_id: 0}, {x: 2}, {upsert: false, writeConcern: {w: 1}})); assert.writeOK(coll.remove({_id: 0}, {justOne: true, writeConcern: {w: 1}})); @@ -61,11 +53,11 @@ assert.commandWorked(secondary.getDB('admin').runCommand( {configureFailPoint: 'initialSyncHangBeforeCopyingDatabases', mode: 'off'})); - checkLog(secondary, 'update of non-mod failed'); - checkLog(secondary, 'adding missing object'); + checkLog.contains(secondary, 'update of non-mod failed'); + checkLog.contains(secondary, 'adding missing object'); - checkLog(secondary, - 'initial sync - initialSyncHangBeforeGettingMissingDocument fail point enabled'); + checkLog.contains( + secondary, 'initial sync - initialSyncHangBeforeGettingMissingDocument fail point enabled'); var doc = {_id: 0, x: 3}; // Re-insert deleted document. assert.writeOK(coll.insert(doc, {writeConcern: {w: 1}})); @@ -78,10 +70,10 @@ assert.commandWorked(secondary.getDB('admin').runCommand( {configureFailPoint: 'initialSyncHangBeforeGettingMissingDocument', mode: 'off'})); - checkLog(secondary, 'inserted missing doc:'); + checkLog.contains(secondary, 'inserted missing doc:'); secondary.getDB('test').setLogLevel(0, 'replication'); - checkLog(secondary, 'initial sync done'); + checkLog.contains(secondary, 'initial sync done'); replSet.awaitReplication(); replSet.awaitSecondaryNodes(); diff --git a/jstests/replsets/read_after_optime.js b/jstests/replsets/read_after_optime.js index e7e911c5722..ced5a83a8c1 100644 --- a/jstests/replsets/read_after_optime.js +++ b/jstests/replsets/read_after_optime.js @@ -2,6 +2,7 @@ (function() { "use strict"; + load("jstests/libs/check_log.js"); var replTest = new ReplSetTest({nodes: 2}); replTest.startSet(); @@ -33,30 +34,6 @@ ErrorCodes.ExceededTimeLimit); }; - var countLogMessages = function(msg) { - var total = 0; - var logMessages = assert.commandWorked(testDB.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - total++; - } - } - return total; - }; - - var checkLog = function(msg, expectedCount) { - var count; - assert.soon( - function() { - count = countLogMessages(msg); - return expectedCount == count; - }, - 'Expected ' + expectedCount + ', but instead saw ' + count + - ' log entries containing the following message: ' + msg, - 60000, - 300); - }; - // Run the time out test 3 times with replication debug log level increased to 2 // for first and last run. The time out message should be logged twice. testDB.setLogLevel(2, 'command'); @@ -65,7 +42,7 @@ var msg = 'Command on database ' + testDB.getName() + ' timed out waiting for read concern to be satisfied. Command:'; - checkLog(msg, 1); + checkLog.containsWithCount(testDB.getMongo(), msg, 1); // Read concern timed out message should not be logged. runTimeoutTest(); @@ -74,7 +51,7 @@ runTimeoutTest(); testDB.setLogLevel(0, 'command'); - checkLog(msg, 2); + checkLog.containsWithCount(testDB.getMongo(), msg, 2); // Test read on future afterOpTime that will eventually occur. primaryConn.getDB(dbName).parallelShellStarted.drop(); diff --git a/jstests/sharding/config_version_rollback.js b/jstests/sharding/config_version_rollback.js index 2fc5d78c8fc..bb066b8cc80 100644 --- a/jstests/sharding/config_version_rollback.js +++ b/jstests/sharding/config_version_rollback.js @@ -6,23 +6,7 @@ (function() { "use strict"; - - // Wait for fail point message to be logged. - var checkLog = function(node, msg) { - assert.soon( - function() { - var logMessages = assert.commandWorked(node.adminCommand({getLog: 'global'})).log; - for (var i = 0; i < logMessages.length; i++) { - if (logMessages[i].indexOf(msg) != -1) { - return true; - } - } - return false; - }, - 'Did not see a log entry for ' + node + ' containing the following message: ' + msg, - 60000, - 1000); - }; + load("jstests/libs/check_log.js"); // The config.version document is written on transition to primary. We need to ensure this // config.version document is rolled back for this test. @@ -70,7 +54,7 @@ // Ensure the primary is waiting to write the config.version document before stopping the oplog // fetcher on the secondaries. - checkLog( + checkLog.contains( origPriConn, 'transition to primary - transitionToPrimaryHangBeforeInitializingConfigDatabase fail point enabled.'); |