diff options
author | Henrik Edin <henrik.edin@mongodb.com> | 2020-01-21 20:23:50 +0000 |
---|---|---|
committer | evergreen <evergreen@mongodb.com> | 2020-01-21 20:23:50 +0000 |
commit | b7846ff4dceec36e344b0f87c48783dffa2c6a32 (patch) | |
tree | 73068bb126bf19901e75bb972a941f17c9759754 /src | |
parent | 41b3d7da7c763e304bc8f4056d0d31d200742e0b (diff) | |
download | mongo-b7846ff4dceec36e344b0f87c48783dffa2c6a32.tar.gz |
SERVER-45583 Unittests are using logv2.
Capture log system uses logv2, tests can handle converted log statements.
Diffstat (limited to 'src')
24 files changed, 472 insertions, 293 deletions
diff --git a/src/mongo/client/fetcher_test.cpp b/src/mongo/client/fetcher_test.cpp index 557f47a5b57..b03ba051978 100644 --- a/src/mongo/client/fetcher_test.cpp +++ b/src/mongo/client/fetcher_test.cpp @@ -837,7 +837,7 @@ TEST_F(FetcherTest, EmptyGetMoreRequestAfterFirstBatchMakesFetcherInactiveAndKil // killCursors command request will be canceled by executor on shutdown. tearDown(); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( "killCursors command task failed: CallbackCanceled: Callback canceled")); } @@ -910,7 +910,7 @@ TEST_F(FetcherTest, UpdateNextActionAfterSecondBatch) { getNet()->runReadyNetworkOperations(); } - ASSERT_EQUALS(1, countLogLinesContaining("killCursors command failed: UnknownError")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("killCursors command failed: UnknownError")); } /** @@ -979,8 +979,8 @@ TEST_F(FetcherTest, ShutdownDuringSecondBatch) { // Fetcher should attempt (unsuccessfully) to schedule a killCursors command. ASSERT_EQUALS(1, - countLogLinesContaining("failed to schedule killCursors command: " - "ShutdownInProgress: Shutdown in progress")); + countTextFormatLogLinesContaining("failed to schedule killCursors command: " + "ShutdownInProgress: Shutdown in progress")); ASSERT_EQUALS(ErrorCodes::ShutdownInProgress, status.code()); } diff --git a/src/mongo/db/repl/apply_ops_test.cpp b/src/mongo/db/repl/apply_ops_test.cpp index 9fe27a8c8a1..85c4c428361 100644 --- a/src/mongo/db/repl/apply_ops_test.cpp +++ b/src/mongo/db/repl/apply_ops_test.cpp @@ -315,7 +315,7 @@ TEST_F(ApplyOpsTest, ApplyOpsPropagatesOplogApplicationMode) { cmdObj, OplogApplication::Mode::kInitialSync, &resultBuilder)); - ASSERT_EQUALS(1, countLogLinesContaining("oplog application mode: InitialSync")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("oplog application mode: InitialSync")); auto docToInsert1 = BSON("_id" << 1); cmdObj = makeApplyOpsWithInsertOperation(nss, uuid, docToInsert1); @@ -325,7 +325,7 @@ TEST_F(ApplyOpsTest, ApplyOpsPropagatesOplogApplicationMode) { cmdObj, OplogApplication::Mode::kSecondary, &resultBuilder)); - ASSERT_EQUALS(1, countLogLinesContaining("oplog application mode: Secondary")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("oplog application mode: Secondary")); stopCapturingLogMessages(); } diff --git a/src/mongo/db/repl/drop_pending_collection_reaper_test.cpp b/src/mongo/db/repl/drop_pending_collection_reaper_test.cpp index 0ac9f2071e6..3d12d1acde4 100644 --- a/src/mongo/db/repl/drop_pending_collection_reaper_test.cpp +++ b/src/mongo/db/repl/drop_pending_collection_reaper_test.cpp @@ -238,7 +238,8 @@ TEST_F(DropPendingCollectionReaperTest, DropCollectionsOlderThanLogsDropCollecti reaper.dropCollectionsOlderThan(opCtx.get(), optime); stopCapturingLogMessages(); - ASSERT_EQUALS(1LL, countLogLinesContaining("Failed to remove drop-pending collection")); + ASSERT_EQUALS(1LL, + countTextFormatLogLinesContaining("Failed to remove drop-pending collection")); } TEST_F(DropPendingCollectionReaperTest, diff --git a/src/mongo/db/repl/oplog_applier_impl_test.cpp b/src/mongo/db/repl/oplog_applier_impl_test.cpp index a851ee49917..6f0c8ae14f8 100644 --- a/src/mongo/db/repl/oplog_applier_impl_test.cpp +++ b/src/mongo/db/repl/oplog_applier_impl_test.cpp @@ -2246,7 +2246,7 @@ TEST_F(OplogApplierImplTest, LogSlowOpApplicationWhenSuccessful) { "wall: new Date(0), o: " "{ _id: 0 } }, took " << applyDuration << "ms"; - ASSERT_EQUALS(1, countLogLinesContaining(expected.str())); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expected.str())); } TEST_F(OplogApplierImplTest, DoNotLogSlowOpApplicationWhenFailed) { @@ -2270,7 +2270,7 @@ TEST_F(OplogApplierImplTest, DoNotLogSlowOpApplicationWhenFailed) { expected << "applied op: CRUD { op: \"i\", ns: \"test.t\", o: { _id: 0 }, ts: Timestamp(1, 1), " "t: 1, h: 1, v: 2 }, took " << applyDuration << "ms"; - ASSERT_EQUALS(0, countLogLinesContaining(expected.str())); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining(expected.str())); } TEST_F(OplogApplierImplTest, DoNotLogNonSlowOpApplicationWhenSuccessful) { @@ -2294,7 +2294,7 @@ TEST_F(OplogApplierImplTest, DoNotLogNonSlowOpApplicationWhenSuccessful) { expected << "applied op: CRUD { op: \"i\", ns: \"test.t\", o: { _id: 0 }, ts: Timestamp(1, 1), " "t: 1, h: 1, v: 2 }, took " << applyDuration << "ms"; - ASSERT_EQUALS(0, countLogLinesContaining(expected.str())); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining(expected.str())); } class OplogApplierImplTxnTableTest : public OplogApplierImplTest { public: diff --git a/src/mongo/db/repl/replication_coordinator_impl_elect_v1_test.cpp b/src/mongo/db/repl/replication_coordinator_impl_elect_v1_test.cpp index 06c6cd8b6cb..bb44ed0bcd4 100644 --- a/src/mongo/db/repl/replication_coordinator_impl_elect_v1_test.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl_elect_v1_test.cpp @@ -268,7 +268,7 @@ TEST_F(ReplCoordTest, ElectionSucceedsWhenAllNodesVoteYea) { ASSERT_EQ(1, lastVote.getValue().getTerm()); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("election succeeded")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("election succeeded")); // Check that the numElectionTimeoutsCalled and the numElectionTimeoutsSuccessful election // metrics have been incremented, and that none of the metrics that track the number of @@ -322,7 +322,7 @@ TEST_F(ReplCoordTest, ElectionSucceedsWhenMaxSevenNodesVoteYea) { ASSERT_EQ(1, lastVote.getValue().getTerm()); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("election succeeded")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("election succeeded")); } TEST_F(ReplCoordTest, ElectionFailsWhenInsufficientVotesAreReceivedDuringDryRun) { @@ -388,8 +388,9 @@ TEST_F(ReplCoordTest, ElectionFailsWhenInsufficientVotesAreReceivedDuringDryRun) } net->exitNetwork(); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, countLogLinesContaining("not running for primary, we received insufficient votes")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "not running for primary, we received insufficient votes")); // Check that the node's election candidate metrics have been cleared, since it lost the dry-run // election and will not become primary. @@ -453,8 +454,9 @@ TEST_F(ReplCoordTest, ElectionFailsWhenDryRunResponseContainsANewerTerm) { net->exitNetwork(); getReplCoord()->waitForElectionFinish_forTest(); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, countLogLinesContaining("not running for primary, we have been superseded already")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "not running for primary, we have been superseded already")); } TEST_F(ReplCoordTest, NodeWillNotStandForElectionDuringHeartbeatReconfig) { @@ -571,8 +573,8 @@ TEST_F(ReplCoordTest, NodeWillNotStandForElectionDuringHeartbeatReconfig) { stopCapturingLogMessages(); // ensure node does not stand for election ASSERT_EQUALS(1, - countLogLinesContaining("Not standing for election; processing " - "a configuration change")); + countTextFormatLogLinesContaining("Not standing for election; processing " + "a configuration change")); globalFailPointRegistry().find("blockHeartbeatReconfigFinish")->setMode(FailPoint::off); } @@ -621,8 +623,9 @@ TEST_F(ReplCoordTest, ElectionFailsWhenInsufficientVotesAreReceivedDuringRequest getReplCoord()->waitForElectionFinish_forTest(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, - countLogLinesContaining("not becoming primary, we received insufficient votes")); + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("not becoming primary, we received insufficient votes")); } TEST_F(ReplCoordTest, TransitionToRollbackFailsWhenElectionInProgress) { @@ -714,8 +717,9 @@ TEST_F(ReplCoordTest, ElectionFailsWhenVoteRequestResponseContainsANewerTerm) { getReplCoord()->waitForElectionFinish_forTest(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, - countLogLinesContaining("not becoming primary, we have been superseded already")); + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("not becoming primary, we have been superseded already")); // Check that the node's election candidate metrics have been cleared, since it lost the actual // election and will not become primary. @@ -757,7 +761,7 @@ TEST_F(ReplCoordTest, ElectionFailsWhenTermChangesDuringDryRun) { stopCapturingLogMessages(); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( "not running for primary, we have been superseded already during dry run")); } @@ -808,8 +812,9 @@ TEST_F(ReplCoordTest, ElectionFailsWhenTermChangesDuringActualElection) { net->exitNetwork(); getReplCoord()->waitForElectionFinish_forTest(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, - countLogLinesContaining("not becoming primary, we have been superseded already")); + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("not becoming primary, we have been superseded already")); } class TakeoverTest : public ReplCoordTest { @@ -897,10 +902,11 @@ public: ASSERT_EQ(lastVoteExpected.getTerm(), lastVote.getValue().getTerm()); if (reason == StartElectionReasonEnum::kPriorityTakeover) { - ASSERT_EQUALS(1, - countLogLinesContaining("Starting an election for a priority takeover")); + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("Starting an election for a priority takeover")); } - ASSERT_EQUALS(1, countLogLinesContaining("election succeeded")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("election succeeded")); } private: @@ -1136,10 +1142,10 @@ TEST_F(TakeoverTest, PrefersPriorityToCatchupTakeoverIfNodeHasHighestPriority) { ASSERT_FALSE(replCoord->getCatchupTakeover_forTest()); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, - countLogLinesContaining("I can take over the primary because I have a higher priority, " - "the highest priority in the replica set, and fresher data.")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "I can take over the primary because I have a higher priority, " + "the highest priority in the replica set, and fresher data.")); } TEST_F(TakeoverTest, CatchupTakeoverNotScheduledTwice) { @@ -1322,13 +1328,15 @@ TEST_F(TakeoverTest, CatchupTakeoverCallbackCanceledIfElectionTimeoutRuns) { stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Starting an election, since we've seen no PRIMARY")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Starting an election, since we've seen no PRIMARY")); // Make sure catchup takeover never happend and CatchupTakeover callback was canceled. ASSERT_FALSE(replCoord->getCatchupTakeover_forTest()); ASSERT(replCoord->getMemberState().secondary()); - ASSERT_EQUALS(1, countLogLinesContaining("Canceling catchup takeover callback")); - ASSERT_EQUALS(0, countLogLinesContaining("Starting an election for a catchup takeover")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Canceling catchup takeover callback")); + ASSERT_EQUALS(0, + countTextFormatLogLinesContaining("Starting an election for a catchup takeover")); } TEST_F(TakeoverTest, CatchupTakeoverCanceledIfTransitionToRollback) { @@ -1387,8 +1395,9 @@ TEST_F(TakeoverTest, CatchupTakeoverCanceledIfTransitionToRollback) { // Make sure catchup takeover never happend and CatchupTakeover callback was canceled. ASSERT_FALSE(replCoord->getCatchupTakeover_forTest()); - ASSERT_EQUALS(1, countLogLinesContaining("Canceling catchup takeover callback")); - ASSERT_EQUALS(0, countLogLinesContaining("Starting an election for a catchup takeover")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Canceling catchup takeover callback")); + ASSERT_EQUALS(0, + countTextFormatLogLinesContaining("Starting an election for a catchup takeover")); } TEST_F(TakeoverTest, SuccessfulCatchupTakeover) { @@ -1446,7 +1455,8 @@ TEST_F(TakeoverTest, SuccessfulCatchupTakeover) { // Since the heartbeats go through the catchupTakeoverTimeout, this log // message happens already (otherwise it would happen in performSuccessfulTakeover). - ASSERT_EQUALS(1, countLogLinesContaining("Starting an election for a catchup takeover")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining("Starting an election for a catchup takeover")); LastVote lastVoteExpected = LastVote(replCoord->getTerm() + 1, 0); performSuccessfulTakeover( @@ -1524,7 +1534,8 @@ TEST_F(TakeoverTest, CatchupTakeoverDryRunFailsPrimarySaysNo) { now = respondToHeartbeatsUntil( config, catchupTakeoverTime, HostAndPort("node2", 12345), behindOptime); - ASSERT_EQUALS(1, countLogLinesContaining("Starting an election for a catchup takeover")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining("Starting an election for a catchup takeover")); // Simulate a dry run where the primary has caught up and is now ahead of the // node trying to do the catchup takeover. All the secondary nodes respond @@ -1570,7 +1581,7 @@ TEST_F(TakeoverTest, CatchupTakeoverDryRunFailsPrimarySaysNo) { // Make sure an election wasn't called for and that we are still secondary. ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( "not running for primary, the current primary responded no in the dry run")); ASSERT(replCoord->getMemberState().secondary()); } @@ -1630,7 +1641,8 @@ TEST_F(TakeoverTest, PrimaryCatchesUpBeforeCatchupTakeover) { // Make sure we're secondary and that no catchup takeover election happened. ASSERT(replCoord->getMemberState().secondary()); ASSERT_FALSE(replCoord->getCatchupTakeover_forTest()); - ASSERT_EQUALS(1, countLogLinesContaining("Not starting an election for a catchup takeover")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Not starting an election for a catchup takeover")); } TEST_F(TakeoverTest, PrimaryCatchesUpBeforeHighPriorityNodeCatchupTakeover) { @@ -1690,7 +1702,8 @@ TEST_F(TakeoverTest, PrimaryCatchesUpBeforeHighPriorityNodeCatchupTakeover) { // Make sure we're secondary and that no catchup takeover election happens. ASSERT(replCoord->getMemberState().secondary()); ASSERT_FALSE(replCoord->getCatchupTakeover_forTest()); - ASSERT_EQUALS(1, countLogLinesContaining("Not starting an election for a catchup takeover")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Not starting an election for a catchup takeover")); // Make sure that the priority takeover has now been scheduled and at the // correct time. @@ -1867,8 +1880,9 @@ TEST_F(TakeoverTest, DontCallForPriorityTakeoverWhenLaggedSameSecond) { stopCapturingLogMessages(); ASSERT(replCoord->getMemberState().secondary()); - ASSERT_EQUALS(1, - countLogLinesContaining("Not standing for election because member is not " + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("Not standing for election because member is not " "caught up enough to the most up-to-date member to " "call for priority takeover")); @@ -1951,8 +1965,9 @@ TEST_F(TakeoverTest, DontCallForPriorityTakeoverWhenLaggedDifferentSecond) { stopCapturingLogMessages(); ASSERT(replCoord->getMemberState().secondary()); - ASSERT_EQUALS(1, - countLogLinesContaining("Not standing for election because member is not " + ASSERT_EQUALS( + 1, + countTextFormatLogLinesContaining("Not standing for election because member is not " "caught up enough to the most up-to-date member to " "call for priority takeover")); @@ -2255,7 +2270,9 @@ TEST_F(PrimaryCatchUpTest, PrimaryDoesNotNeedToCatchUp) { ASSERT_EQUALS(2, count); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Caught up to the latest optime known via heartbeats")); + ASSERT_EQ( + 1, + countTextFormatLogLinesContaining("Caught up to the latest optime known via heartbeats")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2309,7 +2326,8 @@ TEST_F(PrimaryCatchUpTest, CatchupSucceeds) { advanceMyLastAppliedOpTime(time2, Date_t() + Seconds(time2.getSecs())); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Caught up to the latest known optime successfully")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Caught up to the latest known optime successfully")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2343,7 +2361,7 @@ TEST_F(PrimaryCatchUpTest, CatchupTimeout) { }); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Catchup timed out")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Catchup timed out")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2382,7 +2400,9 @@ TEST_F(PrimaryCatchUpTest, CannotSeeAllNodes) { }); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Caught up to the latest optime known via heartbeats")); + ASSERT_EQ( + 1, + countTextFormatLogLinesContaining("Caught up to the latest optime known via heartbeats")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2422,7 +2442,9 @@ TEST_F(PrimaryCatchUpTest, HeartbeatTimeout) { }); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Caught up to the latest optime known via heartbeats")); + ASSERT_EQ( + 1, + countTextFormatLogLinesContaining("Caught up to the latest optime known via heartbeats")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2459,9 +2481,9 @@ TEST_F(PrimaryCatchUpTest, PrimaryStepsDownBeforeHeartbeatRefreshing) { ASSERT_TRUE(getReplCoord()->getMemberState().secondary()); ASSERT(getReplCoord()->getApplierState() == ApplierState::Running); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Exited primary catch-up mode")); - ASSERT_EQUALS(0, countLogLinesContaining("Caught up to the latest")); - ASSERT_EQUALS(0, countLogLinesContaining("Catchup timed out")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Exited primary catch-up mode")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Caught up to the latest")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Catchup timed out")); auto opCtx = makeOperationContext(); Lock::GlobalLock lock(opCtx.get(), MODE_IX); ASSERT_FALSE(getReplCoord()->canAcceptWritesForDatabase(opCtx.get(), "test")); @@ -2507,9 +2529,9 @@ TEST_F(PrimaryCatchUpTest, PrimaryStepsDownDuringCatchUp) { // replyHeartbeatsAndRunUntil(getNet()->now() + config.getCatchUpTimeoutPeriod()); ASSERT(getReplCoord()->getApplierState() == ApplierState::Running); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Exited primary catch-up mode")); - ASSERT_EQUALS(0, countLogLinesContaining("Caught up to the latest")); - ASSERT_EQUALS(0, countLogLinesContaining("Catchup timed out")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Exited primary catch-up mode")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Caught up to the latest")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Catchup timed out")); auto opCtx = makeOperationContext(); Lock::GlobalLock lock(opCtx.get(), MODE_IX); ASSERT_FALSE(getReplCoord()->canAcceptWritesForDatabase(opCtx.get(), "test")); @@ -2551,7 +2573,7 @@ TEST_F(PrimaryCatchUpTest, PrimaryStepsDownDuringDrainMode) { advanceMyLastAppliedOpTime(time2, Date_t() + Seconds(time2.getSecs())); ASSERT(replCoord->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Caught up to the latest")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Caught up to the latest")); // Check that the number of elections requiring primary catchup was incremented. auto opCtx = makeOperationContext(); @@ -2636,7 +2658,7 @@ TEST_F(PrimaryCatchUpTest, FreshestNodeBecomesAvailableLater) { // The node is still in catchup mode, but the target optime has been set. ASSERT(getReplCoord()->getApplierState() == ApplierState::Running); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Heartbeats updated catchup target optime")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Heartbeats updated catchup target optime")); ASSERT_EQUALS(time3, ReplicationMetrics::get(getServiceContext()).getTargetCatchupOpTime_forTesting()); @@ -2658,7 +2680,7 @@ TEST_F(PrimaryCatchUpTest, FreshestNodeBecomesAvailableLater) { // The node is still in catchup mode, but the target optime has been updated. ASSERT(getReplCoord()->getApplierState() == ApplierState::Running); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Heartbeats updated catchup target optime")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Heartbeats updated catchup target optime")); ASSERT_EQUALS(time4, ReplicationMetrics::get(getServiceContext()).getTargetCatchupOpTime_forTesting()); @@ -2671,7 +2693,7 @@ TEST_F(PrimaryCatchUpTest, FreshestNodeBecomesAvailableLater) { advanceMyLastAppliedOpTime(time4, Date_t() + Seconds(time4.getSecs())); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQ(1, countLogLinesContaining("Caught up to the latest")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Caught up to the latest")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2730,9 +2752,9 @@ TEST_F(PrimaryCatchUpTest, InfiniteTimeoutAndAbort) { ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Exited primary catch-up mode")); - ASSERT_EQUALS(0, countLogLinesContaining("Caught up to the latest")); - ASSERT_EQUALS(0, countLogLinesContaining("Catchup timed out")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Exited primary catch-up mode")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Caught up to the latest")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Catchup timed out")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2761,7 +2783,7 @@ TEST_F(PrimaryCatchUpTest, ZeroTimeout) { ReplSetConfig config = setUp3NodeReplSetAndRunForElection(time1, 0); ASSERT(getReplCoord()->getApplierState() == ApplierState::Draining); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Skipping primary catchup")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Skipping primary catchup")); auto opCtx = makeOperationContext(); signalDrainComplete(opCtx.get()); Lock::GlobalLock lock(opCtx.get(), MODE_IX); @@ -2802,9 +2824,9 @@ TEST_F(PrimaryCatchUpTest, CatchUpFailsDueToPrimaryStepDown) { ASSERT(getReplCoord()->getApplierState() == ApplierState::Running); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Exited primary catch-up mode")); - ASSERT_EQUALS(0, countLogLinesContaining("Caught up to the latest")); - ASSERT_EQUALS(0, countLogLinesContaining("Catchup timed out")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("Exited primary catch-up mode")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Caught up to the latest")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("Catchup timed out")); // Check that the number of elections requiring primary catchup was incremented. ASSERT_EQ(1, ReplicationMetrics::get(opCtx.get()).getNumCatchUps_forTesting()); diff --git a/src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp b/src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp index 5822e6c5506..e79f7bc8866 100644 --- a/src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl_reconfig_test.cpp @@ -605,8 +605,9 @@ TEST_F(ReplCoordTest, NodeDoesNotAcceptHeartbeatReconfigWhileInTheMidstOfReconfi // respond to reconfig's quorum check so that we can join that thread and exit cleanly net->exitNetwork(); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, countLogLinesContaining("because already in the midst of a configuration process")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "because already in the midst of a configuration process")); shutdown(opCtx.get()); reconfigThread.join(); setMinimumLoggedSeverity(logger::LogSeverity::Log()); diff --git a/src/mongo/db/repl/replication_coordinator_impl_test.cpp b/src/mongo/db/repl/replication_coordinator_impl_test.cpp index d97dedf157f..a708941155d 100644 --- a/src/mongo/db/repl/replication_coordinator_impl_test.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl_test.cpp @@ -192,7 +192,7 @@ TEST_F(ReplCoordTest, NodeEntersRemovedStateWhenStartingUpWithALocalConfigWhichL << "node2:54321"))), HostAndPort("node3", 12345)); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("NodeNotFound")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("NodeNotFound")); ASSERT_EQUALS(MemberState::RS_REMOVED, getReplCoord()->getMemberState().s); } @@ -207,7 +207,7 @@ TEST_F(ReplCoordTest, << "node1:12345"))), HostAndPort("node1", 12345)); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("reports set name of notMySet,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("reports set name of notMySet,")); ASSERT_EQUALS(MemberState::RS_REMOVED, getReplCoord()->getMemberState().s); } @@ -215,7 +215,7 @@ TEST_F(ReplCoordTest, NodeEntersStartupStateWhenStartingUpWithNoLocalConfig) { startCapturingLogMessages(); start(); stopCapturingLogMessages(); - ASSERT_EQUALS(3, countLogLinesContaining("Did not find local ")); + ASSERT_EQUALS(3, countTextFormatLogLinesContaining("Did not find local ")); ASSERT_EQUALS(MemberState::RS_STARTUP, getReplCoord()->getMemberState().s); } @@ -3534,7 +3534,8 @@ TEST_F(ReplCoordTest, LogAMessageWhenShutDownBeforeReplicationStartUpFinished) { getReplCoord()->shutdown(opCtx.get()); } stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("shutdown() called before startup() finished")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining("shutdown() called before startup() finished")); } TEST_F(ReplCoordTest, DoNotProcessSelfWhenUpdatePositionContainsInfoAboutSelf) { @@ -5671,15 +5672,15 @@ TEST_F(ReplCoordTest, CancelAndRescheduleElectionTimeoutLogging) { // Setting mode to secondary should schedule the election timeout. ReplicationCoordinatorImpl* replCoord = getReplCoord(); ASSERT_OK(replCoord->setFollowerMode(MemberState::RS_SECONDARY)); - ASSERT_EQ(1, countLogLinesContaining("Scheduling election timeout callback")); - ASSERT_EQ(0, countLogLinesContaining("Rescheduling election timeout callback")); - ASSERT_EQ(0, countLogLinesContaining("Canceling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Scheduling election timeout callback")); + ASSERT_EQ(0, countTextFormatLogLinesContaining("Rescheduling election timeout callback")); + ASSERT_EQ(0, countTextFormatLogLinesContaining("Canceling election timeout callback")); // Scheduling again should produce the "rescheduled", not the "scheduled", message . replCoord->cancelAndRescheduleElectionTimeout(); - ASSERT_EQ(1, countLogLinesContaining("Scheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Rescheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Canceling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Scheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Rescheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Canceling election timeout callback")); auto net = getNet(); net->enterNetwork(); @@ -5703,9 +5704,9 @@ TEST_F(ReplCoordTest, CancelAndRescheduleElectionTimeoutLogging) { net->exitNetwork(); // The election should have scheduled (not rescheduled) another timeout. - ASSERT_EQ(2, countLogLinesContaining("Scheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Rescheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Canceling election timeout callback")); + ASSERT_EQ(2, countTextFormatLogLinesContaining("Scheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Rescheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Canceling election timeout callback")); setMinimumLoggedSeverity(logger::LogComponent::kReplicationElection, logger::LogSeverity::Debug(4)); @@ -5716,9 +5717,9 @@ TEST_F(ReplCoordTest, CancelAndRescheduleElectionTimeoutLogging) { replCoord->cancelAndRescheduleElectionTimeout(); // We should not see this reschedule because it should be at log level 5. - ASSERT_EQ(2, countLogLinesContaining("Scheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Rescheduling election timeout callback")); - ASSERT_EQ(1, countLogLinesContaining("Canceling election timeout callback")); + ASSERT_EQ(2, countTextFormatLogLinesContaining("Scheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Rescheduling election timeout callback")); + ASSERT_EQ(1, countTextFormatLogLinesContaining("Canceling election timeout callback")); net->enterNetwork(); until = electionTimeoutWhen + Milliseconds(1001); @@ -5729,9 +5730,9 @@ TEST_F(ReplCoordTest, CancelAndRescheduleElectionTimeoutLogging) { stopCapturingLogMessages(); // We should see this reschedule at level 4 because it has been over 1 sec since we logged // at level 4. - ASSERT_EQ(2, countLogLinesContaining("Scheduling election timeout callback")); - ASSERT_EQ(2, countLogLinesContaining("Rescheduling election timeout callback")); - ASSERT_EQ(2, countLogLinesContaining("Canceling election timeout callback")); + ASSERT_EQ(2, countTextFormatLogLinesContaining("Scheduling election timeout callback")); + ASSERT_EQ(2, countTextFormatLogLinesContaining("Rescheduling election timeout callback")); + ASSERT_EQ(2, countTextFormatLogLinesContaining("Canceling election timeout callback")); } TEST_F(ReplCoordTest, AdvanceCommittedSnapshotToMostRecentSnapshotPriorToOpTimeWhenOpTimeChanges) { diff --git a/src/mongo/db/repl/replication_recovery_test.cpp b/src/mongo/db/repl/replication_recovery_test.cpp index c633e981542..4831a612b7e 100644 --- a/src/mongo/db/repl/replication_recovery_test.cpp +++ b/src/mongo/db/repl/replication_recovery_test.cpp @@ -1323,7 +1323,8 @@ TEST_F(ReplicationRecoveryTest, RecoverFromOplogUpToWithEmptyOplog) { recovery.recoverFromOplogUpTo(opCtx, Timestamp(5, 5)); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("No stored oplog entries to apply for recovery.")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("No stored oplog entries to apply for recovery.")); _assertDocsInTestCollection(opCtx, {}); ASSERT_EQ(getConsistencyMarkers()->getAppliedThrough(opCtx), OpTime(Timestamp(0, 0), 1)); } diff --git a/src/mongo/db/repl/rs_rollback_test.cpp b/src/mongo/db/repl/rs_rollback_test.cpp index 462ca0f708c..a5b89690129 100644 --- a/src/mongo/db/repl/rs_rollback_test.cpp +++ b/src/mongo/db/repl/rs_rollback_test.cpp @@ -497,7 +497,8 @@ TEST_F(RSRollbackTest, RollbackInsertDocumentWithNoId) { stopCapturingLogMessages(); ASSERT_EQUALS(ErrorCodes::UnrecoverableRollbackError, status.code()); ASSERT_STRING_CONTAINS(status.reason(), "unable to determine common point"); - ASSERT_EQUALS(1, countLogLinesContaining("Cannot roll back op with no _id. ns: test.t,")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Cannot roll back op with no _id. ns: test.t,")); ASSERT_FALSE(rollbackSource.called); } @@ -533,11 +534,11 @@ TEST_F(RSRollbackTest, RollbackCreateIndexCommand) { _coordinator, _replicationProcess.get())); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, - countLogLinesContaining(str::stream() - << "Dropped index in rollback for collection: " << nss.toString() - << ", UUID: " << options.uuid->toString() << ", index: a_1")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + str::stream() + << "Dropped index in rollback for collection: " << nss.toString() + << ", UUID: " << options.uuid->toString() << ", index: a_1")); { Lock::DBLock dbLock(_opCtx.get(), nss.db(), MODE_S); auto indexCatalog = collection->getIndexCatalog(); @@ -576,7 +577,8 @@ TEST_F(RSRollbackTest, RollbackCreateIndexCommandIndexNotInCatalog) { _coordinator, _replicationProcess.get())); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Rollback failed to drop index a_1 in test.t")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining("Rollback failed to drop index a_1 in test.t")); { Lock::DBLock dbLock(_opCtx.get(), "test", MODE_S); auto indexCatalog = collection->getIndexCatalog(); @@ -785,12 +787,12 @@ TEST_F(RSRollbackTest, RollingBackDropAndCreateOfSameIndexNameWithDifferentSpecs ASSERT(indexCatalog); ASSERT_EQUALS(2, indexCatalog->numIndexesReady(_opCtx.get())); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( str::stream() << "Dropped index in rollback for collection: " << nss.toString() << ", UUID: " << options.uuid->toString() << ", index: a_1")); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( str::stream() << "Created index in rollback for collection: " << nss.toString() << ", UUID: " << options.uuid->toString() << ", index: a_1")); @@ -840,7 +842,7 @@ TEST_F(RSRollbackTest, RollbackCreateIndexCommandMissingIndexName) { ASSERT_EQUALS(ErrorCodes::UnrecoverableRollbackError, status.code()); ASSERT_STRING_CONTAINS(status.reason(), "unable to determine common point"); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( "Missing index name in createIndexes operation on rollback, document: ")); } @@ -1982,7 +1984,7 @@ TEST_F(RSRollbackTest, RollbackCollectionModificationCommand) { stopCapturingLogMessages(); ASSERT_TRUE(rollbackSource.called); - for (const auto& message : getCapturedLogMessages()) { + for (const auto& message : getCapturedTextFormatLogMessages()) { ASSERT_TRUE(message.find("ignoring op with no _id during rollback. ns: test.t") == std::string::npos); } @@ -2765,7 +2767,8 @@ TEST_F(RSRollbackTest, RollbackReturnsImmediatelyOnFailureToTransitionToRollback _replicationProcess.get()); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("Cannot transition from SECONDARY to ROLLBACK")); + ASSERT_EQUALS( + 1, countTextFormatLogLinesContaining("Cannot transition from SECONDARY to ROLLBACK")); ASSERT_EQUALS(MemberState(MemberState::RS_SECONDARY), _coordinator->getMemberState()); } @@ -2810,8 +2813,9 @@ TEST_F(RSRollbackTest, RollbackLogsRetryMessageAndReturnsOnNonUnrecoverableRollb noopSleepSecsFn); stopCapturingLogMessages(); - ASSERT_EQUALS( - 1, countLogLinesContaining("Rollback cannot complete at this time (retrying later)")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "Rollback cannot complete at this time (retrying later)")); ASSERT_EQUALS(MemberState(MemberState::RS_RECOVERING), _coordinator->getMemberState()); } diff --git a/src/mongo/db/repl/topology_coordinator_v1_test.cpp b/src/mongo/db/repl/topology_coordinator_v1_test.cpp index 69f04103eb1..ed99ee92be6 100644 --- a/src/mongo/db/repl/topology_coordinator_v1_test.cpp +++ b/src/mongo/db/repl/topology_coordinator_v1_test.cpp @@ -106,7 +106,7 @@ protected: } int64_t countLogLinesContaining(const std::string& needle) { - const auto& msgs = getCapturedLogMessages(); + const auto& msgs = getCapturedTextFormatLogMessages(); return std::count_if( msgs.begin(), msgs.end(), [&](const auto& s) { return stringContains(s, needle); }); } diff --git a/src/mongo/db/repl/vote_requester_test.cpp b/src/mongo/db/repl/vote_requester_test.cpp index dd8dedb0ccb..94ba342ca11 100644 --- a/src/mongo/db/repl/vote_requester_test.cpp +++ b/src/mongo/db/repl/vote_requester_test.cpp @@ -95,7 +95,7 @@ public: protected: int64_t countLogLinesContaining(const std::string& needle) { - const auto& msgs = getCapturedLogMessages(); + const auto& msgs = getCapturedTextFormatLogMessages(); return std::count_if( msgs.begin(), msgs.end(), [&](const auto& s) { return stringContains(s, needle); }); } diff --git a/src/mongo/db/s/transaction_coordinator_test.cpp b/src/mongo/db/s/transaction_coordinator_test.cpp index d21e4caf34b..93083cb9739 100644 --- a/src/mongo/db/s/transaction_coordinator_test.cpp +++ b/src/mongo/db/s/transaction_coordinator_test.cpp @@ -1676,7 +1676,7 @@ TEST_F(TransactionCoordinatorMetricsTest, SimpleTwoPhaseCommitRealCoordinator) { stopCapturingLogMessages(); // Slow log line is logged since the coordination completed successfully. - ASSERT_EQUALS(1, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorIsCanceledWhileInactive) { @@ -1721,7 +1721,7 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorIsCanceledWhileInactive) { stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordinatorIsInactive) { @@ -1764,7 +1764,7 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordina stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1825,7 +1825,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1890,7 +1890,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1957,7 +1957,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -2028,7 +2028,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordinatorIsDeletingDoc) { @@ -2105,19 +2105,19 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordina stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionAtLogLevelOne) { setMinimumLoggedSeverity(logger::LogComponent::kTransaction, logger::LogSeverity::Debug(1)); runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(1, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionAtLogLevelZero) { setMinimumLoggedSeverity(logger::LogComponent::kTransaction, logger::LogSeverity::Log()); runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionsUnderSlowMSThreshold) { @@ -2146,7 +2146,7 @@ TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionsUnderSlowMSThres coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F( @@ -2177,7 +2177,7 @@ TEST_F( coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(0, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionsOverSlowMSThreshold) { @@ -2206,7 +2206,7 @@ TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionsOverSlowMSThreshold) { coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTransactionParameters) { @@ -2214,16 +2214,17 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTransactionParamete BSONObjBuilder lsidBob; _lsid.serialize(&lsidBob); ASSERT_EQUALS(1, - countLogLinesContaining(str::stream() - << "parameters:{ lsid: " << lsidBob.done().toString() - << ", txnNumber: " << _txnNumber)); + countTextFormatLogLinesContaining( + str::stream() << "parameters:{ lsid: " << lsidBob.done().toString() + << ", txnNumber: " << _txnNumber)); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseAndCommitTimestampForCommitDecision) { runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS( - 1, countLogLinesContaining("terminationCause:committed, commitTimestamp: Timestamp(1, 1)")); + ASSERT_EQUALS(1, + countTextFormatLogLinesContaining( + "terminationCause:committed, commitTimestamp: Timestamp(1, 1)")); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseForAbortDecision) { @@ -2246,16 +2247,17 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseFor coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); ASSERT_EQUALS( 1, - countLogLinesContaining("terminationDetails: NoSuchTransaction: from shard s1") + - countLogLinesContaining("terminationDetails: NoSuchTransaction: from shard s2")); + countTextFormatLogLinesContaining("terminationDetails: NoSuchTransaction: from shard s1") + + countTextFormatLogLinesContaining( + "terminationDetails: NoSuchTransaction: from shard s2")); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesNumParticipants) { runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:2")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesStepDurationsAndTotalDuration) { @@ -2331,12 +2333,15 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesStepDurationsAndTot // Note: The waiting for decision acks and deleting coordinator doc durations are not reported. ASSERT_EQUALS(1, - countLogLinesContaining("stepDurations:{ writingParticipantListMicros: " - "100000, waitingForVotesMicros: 100000, " - "writingDecisionMicros: 100000, " - "waitingForDecisionAcksMicros: 100000, " - "deletingCoordinatorDocMicros: 100000 }")); - ASSERT_EQUALS(1, countLogLinesContaining(" 500ms\n") + countLogLinesContaining(" 500ms\r\n")); + countTextFormatLogLinesContaining("stepDurations:{ writingParticipantListMicros: " + "100000, waitingForVotesMicros: 100000, " + "writingDecisionMicros: 100000, " + "waitingForDecisionAcksMicros: 100000, " + "deletingCoordinatorDocMicros: 100000 }")); + const auto& logs = getCapturedTextFormatLogMessages(); + ASSERT_EQUALS(1, std::count_if(logs.begin(), logs.end(), [](const std::string& line) { + return StringData(line).endsWith(" 500ms"); + })); } TEST_F(TransactionCoordinatorMetricsTest, ServerStatusSectionIncludesTotalCreated) { diff --git a/src/mongo/db/transaction_participant_test.cpp b/src/mongo/db/transaction_participant_test.cpp index 90de929be2d..3e6c30ceb23 100644 --- a/src/mongo/db/transaction_participant_test.cpp +++ b/src/mongo/db/transaction_participant_test.cpp @@ -3292,7 +3292,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) { std::string expectedTransactionInfo = "transaction " + txnParticipant.getTransactionInfoForLogForTest( opCtx(), &lockerInfo->stats, true, readConcernArgs); - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowCommit) { @@ -3329,7 +3329,7 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowCommit) { std::string expectedTransactionInfo = "transaction " + txnParticipant.getTransactionInfoForLogForTest( opCtx(), &lockerInfo->stats, true, readConcernArgs); - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { @@ -3372,7 +3372,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { metricValue, false); - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowAbort) { @@ -3419,7 +3419,7 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowAbort) { false, prepareOpTime); - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterExceptionInPrepare) { @@ -3465,7 +3465,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterExceptionInPrepare) { metricValue, false); - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { @@ -3504,7 +3504,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { stopCapturingLogMessages(); std::string expectedTransactionInfo = "transaction parameters"; - ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoVerbosityInfo) { @@ -3525,7 +3525,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoVerbosityInfo) { stopCapturingLogMessages(); // Test that the transaction is not logged. - ASSERT_EQUALS(0, countLogLinesContaining("transaction parameters")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("transaction parameters")); } TEST_F(TransactionsMetricsTest, LogTransactionInfoVerbosityDebug) { @@ -3549,7 +3549,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoVerbosityDebug) { setMinimumLoggedSeverity(logger::LogComponent::kTransaction, logger::LogSeverity::Info()); // Test that the transaction is still logged. - ASSERT_EQUALS(1, countLogLinesContaining("transaction parameters")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction parameters")); } TEST_F(TxnParticipantTest, RollbackResetsInMemoryStateOfPreparedTransaction) { diff --git a/src/mongo/logger/log_function_test.cpp b/src/mongo/logger/log_function_test.cpp index dd4242dbe55..72b3a78d3db 100644 --- a/src/mongo/logger/log_function_test.cpp +++ b/src/mongo/logger/log_function_test.cpp @@ -41,6 +41,7 @@ #include "mongo/logger/encoder.h" #include "mongo/logger/log_component.h" #include "mongo/logger/message_event_utf8_encoder.h" +#include "mongo/logv2/text_formatter.h" #include "mongo/util/log.h" #include "mongo/util/str.h" @@ -49,7 +50,7 @@ using namespace mongo::logger; namespace mongo { namespace { -typedef LogTest<MessageEventDetailsEncoder> LogTestDetailsEncoder; +typedef LogTest<MessageEventDetailsEncoder, logv2::TextFormatter> LogTestDetailsEncoder; // Constants for log component test cases. const LogComponent componentA = LogComponent::kCommand; diff --git a/src/mongo/logger/log_manager.cpp b/src/mongo/logger/log_manager.cpp index c167853353f..48eb660324f 100644 --- a/src/mongo/logger/log_manager.cpp +++ b/src/mongo/logger/log_manager.cpp @@ -27,12 +27,17 @@ * it in the license file. */ +#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault + #include "mongo/platform/basic.h" #include "mongo/logger/log_manager.h" #include "mongo/logger/console_appender.h" +#include "mongo/logger/logv2_appender.h" #include "mongo/logger/message_event_utf8_encoder.h" +#include "mongo/logv2/log_domain_global.h" +#include "mongo/util/log.h" namespace mongo { namespace logger { @@ -63,9 +68,15 @@ void LogManager::detachDefaultConsoleAppender() { void LogManager::reattachDefaultConsoleAppender() { invariant(!_defaultAppender); - _defaultAppender = - _globalDomain.attachAppender(std::make_unique<ConsoleAppender<MessageEventEphemeral>>( - std::make_unique<MessageEventDetailsEncoder>())); + if (logV2Enabled()) { + _defaultAppender = _globalDomain.attachAppender( + std::make_unique<logger::LogV2Appender<MessageEventEphemeral>>( + &logv2::LogManager::global().getGlobalDomain(), false)); + } else { + _defaultAppender = + _globalDomain.attachAppender(std::make_unique<ConsoleAppender<MessageEventEphemeral>>( + std::make_unique<MessageEventDetailsEncoder>())); + } } bool LogManager::isDefaultConsoleAppenderAttached() const { diff --git a/src/mongo/logger/log_test.cpp b/src/mongo/logger/log_test.cpp index 3daf413bf9a..dcb4bb671cb 100644 --- a/src/mongo/logger/log_test.cpp +++ b/src/mongo/logger/log_test.cpp @@ -45,6 +45,8 @@ #include "mongo/logger/message_log_domain.h" #include "mongo/logger/rotatable_file_appender.h" #include "mongo/logger/rotatable_file_writer.h" +#include "mongo/logv2/plain_formatter.h" +#include "mongo/logv2/text_formatter.h" #include "mongo/platform/compiler.h" #include "mongo/unittest/unittest.h" #include "mongo/util/concurrency/thread_name.h" @@ -56,8 +58,8 @@ using namespace mongo::logger; namespace mongo { namespace { -typedef LogTest<MessageEventDetailsEncoder> LogTestDetailsEncoder; -typedef LogTest<MessageEventUnadornedEncoder> LogTestUnadornedEncoder; +typedef LogTest<MessageEventDetailsEncoder, logv2::TextFormatter> LogTestDetailsEncoder; +typedef LogTest<MessageEventUnadornedEncoder, logv2::PlainFormatter> LogTestUnadornedEncoder; TEST_F(LogTestUnadornedEncoder, logContext) { logContext("WHA!"); @@ -124,8 +126,8 @@ public: TEST_F(LogTestUnadornedEncoder, LogstreamBuilderReentrance) { log() << "Logging A() -- " << A() << " -- done!" << std::endl; ASSERT_EQUALS(2U, _logLines.size()); - ASSERT_EQUALS(std::string("Golly!\n"), _logLines[0]); - ASSERT_EQUALS(std::string("Logging A() -- Golly! -- done!\n"), _logLines[1]); + ASSERT(StringData(_logLines[0]).startsWith("Golly!")); + ASSERT(StringData(_logLines[1]).startsWith("Logging A() -- Golly! -- done!")); } // @@ -155,14 +157,14 @@ TEST_F(LogTestUnadornedEncoder, MongoLogMacroNoFileScopeLogComponent) { LOG(2) << "This is logged"; LOG(3) << "This is not logged"; ASSERT_EQUALS(1U, _logLines.size()); - ASSERT_EQUALS(std::string("This is logged\n"), _logLines[0]); + ASSERT(StringData(_logLines[0]).startsWith("This is logged")); // MONGO_LOG_COMPONENT _logLines.clear(); MONGO_LOG_COMPONENT(2, componentA) << "This is logged"; MONGO_LOG_COMPONENT(3, componentA) << "This is not logged"; ASSERT_EQUALS(1U, _logLines.size()); - ASSERT_EQUALS(std::string("This is logged\n"), _logLines[0]); + ASSERT(StringData(_logLines[0]).startsWith("This is logged")); } // diff --git a/src/mongo/logger/log_test.h b/src/mongo/logger/log_test.h index a5e8d914454..72c4a12b00f 100644 --- a/src/mongo/logger/log_test.h +++ b/src/mongo/logger/log_test.h @@ -29,6 +29,7 @@ #pragma once +#include <boost/log/core.hpp> #include <sstream> #include <string> #include <vector> @@ -37,7 +38,13 @@ #include "mongo/logger/appender.h" #include "mongo/logger/log_severity.h" #include "mongo/logger/logger.h" +#include "mongo/logger/logv2_appender.h" #include "mongo/logger/message_log_domain.h" +#include "mongo/logv2/component_settings_filter.h" +#include "mongo/logv2/log_capture_backend.h" +#include "mongo/logv2/log_domain.h" +#include "mongo/logv2/log_domain_global.h" +#include "mongo/logv2/log_manager.h" #include "mongo/unittest/unittest.h" #include "mongo/util/log_global_settings.h" @@ -47,19 +54,37 @@ namespace logger { // Used for testing logging framework only. // TODO(schwerin): Have logger write to a different log from the global log, so that tests can // redirect their global log output for examination. -template <typename MessageEventEncoder> +template <typename MessageEventEncoder, typename LOGV2Formatter> class LogTest : public unittest::Test { friend class LogTestAppender; public: LogTest() : _severityOld(getMinimumLogSeverity()) { globalLogDomain()->clearAppenders(); - _appenderHandle = - globalLogDomain()->attachAppender(std::make_unique<LogTestAppender>(this)); + if (logV2Enabled()) { + _appenderHandle = globalLogDomain()->attachAppender( + std::make_unique<LogV2Appender<MessageEventEphemeral>>( + &logv2::LogManager::global().getGlobalDomain(), true)); + + if (!_captureSink) { + _captureSink = logv2::LogCaptureBackend::create(_logLines); + _captureSink->set_filter(logv2::ComponentSettingsFilter( + logv2::LogManager::global().getGlobalDomain(), + logv2::LogManager::global().getGlobalSettings())); + _captureSink->set_formatter(LOGV2Formatter()); + } + boost::log::core::get()->add_sink(_captureSink); + } else { + _appenderHandle = + globalLogDomain()->attachAppender(std::make_unique<LogTestAppender>(this)); + } } virtual ~LogTest() { globalLogDomain()->detachAppender(_appenderHandle); + if (logV2Enabled()) { + boost::log::core::get()->remove_sink(_captureSink); + } setMinimumLoggedSeverity(_severityOld); } @@ -86,6 +111,7 @@ private: }; MessageLogDomain::AppenderHandle _appenderHandle; + boost::shared_ptr<boost::log::sinks::synchronous_sink<logv2::LogCaptureBackend>> _captureSink; }; } // namespace logger diff --git a/src/mongo/logv2/domain_filter.h b/src/mongo/logv2/domain_filter.h index 2fbb8c09268..a84d9086c8d 100644 --- a/src/mongo/logv2/domain_filter.h +++ b/src/mongo/logv2/domain_filter.h @@ -57,5 +57,14 @@ private: const LogDomain::Internal* _domain; }; +class AllLogsFilter : public DomainFilter<AllLogsFilter> { +public: + using DomainFilter::DomainFilter; + + bool filter(boost::log::attribute_value_set const& attrs) const { + return true; + } +}; + } // namespace logv2 } // namespace mongo diff --git a/src/mongo/logv2/log_capture_backend.h b/src/mongo/logv2/log_capture_backend.h new file mode 100644 index 00000000000..640a3623321 --- /dev/null +++ b/src/mongo/logv2/log_capture_backend.h @@ -0,0 +1,60 @@ +/** + * Copyright (C) 2020-present MongoDB, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the Server Side Public License, version 1, + * as published by MongoDB, Inc. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * Server Side Public License for more details. + * + * You should have received a copy of the Server Side Public License + * along with this program. If not, see + * <http://www.mongodb.com/licensing/server-side-public-license>. + * + * As a special exception, the copyright holders give permission to link the + * code of portions of this program with the OpenSSL library under certain + * conditions as described in each individual source file and distribute + * linked combinations including the program with the OpenSSL library. You + * must comply with the Server Side Public License in all respects for + * all of the code used other than as permitted herein. If you modify file(s) + * with this exception, you may extend this exception to your version of the + * file(s), but you are not obligated to do so. If you do not wish to do so, + * delete this exception statement from your version. If you delete this + * exception statement from all source files in the program, then also delete + * it in the license file. + */ + +#pragma once + +#include <boost/log/attributes/attribute_value_set.hpp> +#include <boost/log/core/record_view.hpp> +#include <boost/log/sinks.hpp> +#include <boost/log/utility/formatting_ostream.hpp> +#include <boost/make_shared.hpp> +#include <string> +#include <vector> + +namespace mongo::logv2 { +class LogCaptureBackend + : public boost::log::sinks:: + basic_formatted_sink_backend<char, boost::log::sinks::synchronized_feeding> { +public: + LogCaptureBackend(std::vector<std::string>& lines) : _logLines(lines) {} + + static boost::shared_ptr<boost::log::sinks::synchronous_sink<LogCaptureBackend>> create( + std::vector<std::string>& lines) { + return boost::make_shared<boost::log::sinks::synchronous_sink<LogCaptureBackend>>( + boost::make_shared<LogCaptureBackend>(lines)); + } + + void consume(boost::log::record_view const& rec, string_type const& formatted_string) { + _logLines.push_back(formatted_string); + } + +private: + std::vector<std::string>& _logLines; +}; +} // namespace mongo::logv2 diff --git a/src/mongo/logv2/log_test_v2.cpp b/src/mongo/logv2/log_test_v2.cpp index d333930c514..4e722964893 100644 --- a/src/mongo/logv2/log_test_v2.cpp +++ b/src/mongo/logv2/log_test_v2.cpp @@ -47,6 +47,7 @@ #include "mongo/logv2/constants.h" #include "mongo/logv2/json_formatter.h" #include "mongo/logv2/log.h" +#include "mongo/logv2/log_capture_backend.h" #include "mongo/logv2/log_component.h" #include "mongo/logv2/plain_formatter.h" #include "mongo/logv2/ramlog_sink.h" @@ -162,32 +163,11 @@ BSONObj toBSON(const TypeWithNonMemberFormatting&) { return builder.obj(); } -class LogTestBackend - : public boost::log::sinks:: - basic_formatted_sink_backend<char, boost::log::sinks::synchronized_feeding> { -public: - LogTestBackend(std::vector<std::string>& lines) : _logLines(lines) {} - - static boost::shared_ptr<boost::log::sinks::synchronous_sink<LogTestBackend>> create( - std::vector<std::string>& lines) { - auto backend = boost::make_shared<LogTestBackend>(lines); - return boost::make_shared<boost::log::sinks::synchronous_sink<LogTestBackend>>( - std::move(backend)); - } - - void consume(boost::log::record_view const& rec, string_type const& formatted_string) { - _logLines.push_back(formatted_string); - } - -private: - std::vector<std::string>& _logLines; -}; - class LogDuringInitTester { public: LogDuringInitTester() { std::vector<std::string> lines; - auto sink = LogTestBackend::create(lines); + auto sink = LogCaptureBackend::create(lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(PlainFormatter()); @@ -204,7 +184,7 @@ LogDuringInitTester logDuringInit; TEST_F(LogTestV2, Basic) { std::vector<std::string> lines; - auto sink = LogTestBackend::create(lines); + auto sink = LogCaptureBackend::create(lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(PlainFormatter()); @@ -263,21 +243,21 @@ TEST_F(LogTestV2, Types) { using namespace constants; std::vector<std::string> text; - auto text_sink = LogTestBackend::create(text); + auto text_sink = LogCaptureBackend::create(text); text_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); text_sink->set_formatter(PlainFormatter()); attach(text_sink); std::vector<std::string> json; - auto json_sink = LogTestBackend::create(json); + auto json_sink = LogCaptureBackend::create(json); json_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); json_sink->set_formatter(JSONFormatter()); attach(json_sink); std::vector<std::string> bson; - auto bson_sink = LogTestBackend::create(bson); + auto bson_sink = LogCaptureBackend::create(bson); bson_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); bson_sink->set_formatter(BSONFormatter()); @@ -602,7 +582,7 @@ TEST_F(LogTestV2, Types) { TEST_F(LogTestV2, TextFormat) { std::vector<std::string> lines; - auto sink = LogTestBackend::create(lines); + auto sink = LogCaptureBackend::create(lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(TextFormatter()); @@ -640,14 +620,14 @@ TEST_F(LogTestV2, JsonBsonFormat) { using namespace constants; std::vector<std::string> lines; - auto sink = LogTestBackend::create(lines); + auto sink = LogCaptureBackend::create(lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(JSONFormatter()); attach(sink); std::vector<std::string> linesBson; - auto sinkBson = LogTestBackend::create(linesBson); + auto sinkBson = LogCaptureBackend::create(linesBson); sinkBson->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sinkBson->set_formatter(BSONFormatter()); @@ -815,21 +795,21 @@ TEST_F(LogTestV2, Containers) { using namespace constants; std::vector<std::string> text; - auto text_sink = LogTestBackend::create(text); + auto text_sink = LogCaptureBackend::create(text); text_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); text_sink->set_formatter(PlainFormatter()); attach(text_sink); std::vector<std::string> json; - auto json_sink = LogTestBackend::create(json); + auto json_sink = LogCaptureBackend::create(json); json_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); json_sink->set_formatter(JSONFormatter()); attach(json_sink); std::vector<std::string> bson; - auto bson_sink = LogTestBackend::create(bson); + auto bson_sink = LogCaptureBackend::create(bson); bson_sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); bson_sink->set_formatter(BSONFormatter()); @@ -1014,7 +994,7 @@ TEST_F(LogTestV2, Containers) { TEST_F(LogTestV2, Unicode) { std::vector<std::string> lines; - auto sink = LogTestBackend::create(lines); + auto sink = LogCaptureBackend::create(lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(JSONFormatter()); @@ -1085,21 +1065,21 @@ TEST_F(LogTestV2, Unicode) { TEST_F(LogTestV2, Threads) { std::vector<std::string> linesPlain; - auto plainSink = LogTestBackend::create(linesPlain); + auto plainSink = LogCaptureBackend::create(linesPlain); plainSink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); plainSink->set_formatter(PlainFormatter()); attach(plainSink); std::vector<std::string> linesText; - auto textSink = LogTestBackend::create(linesText); + auto textSink = LogCaptureBackend::create(linesText); textSink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); textSink->set_formatter(TextFormatter()); attach(textSink); std::vector<std::string> linesJson; - auto jsonSink = LogTestBackend::create(linesJson); + auto jsonSink = LogCaptureBackend::create(linesJson); jsonSink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); jsonSink->set_formatter(JSONFormatter()); @@ -1148,7 +1128,7 @@ TEST_F(LogTestV2, Ramlog) { attach(sink); std::vector<std::string> lines; - auto testSink = LogTestBackend::create(lines); + auto testSink = LogCaptureBackend::create(lines); testSink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); testSink->set_formatter(PlainFormatter()); @@ -1169,7 +1149,7 @@ TEST_F(LogTestV2, Ramlog) { TEST_F(LogTestV2, MultipleDomains) { std::vector<std::string> global_lines; - auto sink = LogTestBackend::create(global_lines); + auto sink = LogCaptureBackend::create(global_lines); sink->set_filter(ComponentSettingsFilter(LogManager::global().getGlobalDomain(), LogManager::global().getGlobalSettings())); sink->set_formatter(PlainFormatter()); @@ -1188,7 +1168,7 @@ TEST_F(LogTestV2, MultipleDomains) { LogDomain other_domain(std::make_unique<OtherDomainImpl>()); std::vector<std::string> other_lines; - auto other_sink = LogTestBackend::create(other_lines); + auto other_sink = LogCaptureBackend::create(other_lines); other_sink->set_filter( ComponentSettingsFilter(other_domain, LogManager::global().getGlobalSettings())); other_sink->set_formatter(PlainFormatter()); diff --git a/src/mongo/logv2/log_test_v2.h b/src/mongo/logv2/log_test_v2.h index 44f56dba9a4..334023444f3 100644 --- a/src/mongo/logv2/log_test_v2.h +++ b/src/mongo/logv2/log_test_v2.h @@ -35,14 +35,6 @@ #include "mongo/logv2/log_manager.h" #include "mongo/unittest/unittest.h" -#include <boost/log/attributes/attribute_value_set.hpp> -#include <boost/log/core/record_view.hpp> -#include <boost/log/utility/formatting_ostream.hpp> - -#include <boost/log/sinks.hpp> - -#include <boost/make_shared.hpp> - namespace mongo { namespace logv2 { diff --git a/src/mongo/s/transaction_router_test.cpp b/src/mongo/s/transaction_router_test.cpp index d4847dc63ab..dd2e86df0bc 100644 --- a/src/mongo/s/transaction_router_test.cpp +++ b/src/mongo/s/transaction_router_test.cpp @@ -3055,11 +3055,11 @@ protected: } void assertPrintedExactlyOneSlowLogLine() { - ASSERT_EQUALS(1, countLogLinesContaining("transaction parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction parameters:")); } void assertDidNotPrintSlowLogLine() { - ASSERT_EQUALS(0, countLogLinesContaining("transaction parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("transaction parameters:")); } auto routerTxnMetrics() { @@ -3156,7 +3156,7 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTransactionParameters) { BSONObjBuilder lsidBob; getSessionId().serialize(&lsidBob); ASSERT_EQUALS(1, - countLogLinesContaining( + countTextFormatLogLinesContaining( str::stream() << "parameters:{ lsid: " << lsidBob.done().toString() << ", txnNumber: " << kTxnNumber << ", autocommit: false")); } @@ -3166,7 +3166,10 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsDurationAtEnd) { tickSource()->advance(Milliseconds(111)); assertDurationIs(Milliseconds(111)); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining(" 111ms\n") + countLogLinesContaining(" 111ms\r\n")); + const auto& logs = getCapturedTextFormatLogMessages(); + ASSERT_EQUALS(1, std::count_if(logs.begin(), logs.end(), [](const std::string& line) { + return StringData(line).endsWith(" 111ms"); + })); } TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTimeActiveAndInactive) { @@ -3182,8 +3185,8 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTimeActiveAndInactive) { operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining("timeActiveMicros:111,")); - ASSERT_EQUALS(1, countLogLinesContaining("timeInactiveMicros:222,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("timeActiveMicros:111,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("timeInactiveMicros:222,")); } // @@ -3197,8 +3200,8 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_None) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(0, countLogLinesContaining(readConcern.toBSON()["readConcern"])); - ASSERT_EQUALS(0, countLogLinesContaining("globalReadTimestamp:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("globalReadTimestamp:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Local) { @@ -3208,8 +3211,8 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Local) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining(readConcern.toBSON()["readConcern"])); - ASSERT_EQUALS(0, countLogLinesContaining("globalReadTimestamp:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("globalReadTimestamp:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Majority) { @@ -3219,8 +3222,8 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Majority) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining(readConcern.toBSON()["readConcern"])); - ASSERT_EQUALS(0, countLogLinesContaining("globalReadTimestamp:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("globalReadTimestamp:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Snapshot) { @@ -3230,8 +3233,8 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Snapshot) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining(readConcern.toBSON()["readConcern"])); - ASSERT_EQUALS(1, countLogLinesContaining("globalReadTimestamp:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("globalReadTimestamp:")); } // @@ -3242,65 +3245,65 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_NoShards) { beginSlowTxnWithDefaultTxnNumber(); runNoShardCommit(); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:noShards,")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:0")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:noShards,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:0")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(0, countLogLinesContaining("coordinator:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_SingleShard) { beginSlowTxnWithDefaultTxnNumber(); runSingleShardCommit(); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:singleShard,")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:1")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleShard,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(0, countLogLinesContaining("coordinator:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_SingleWriteShard) { beginSlowTxnWithDefaultTxnNumber(); runSingleWriteShardCommit(); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:singleWriteShard,")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleWriteShard,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(0, countLogLinesContaining("coordinator:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_ReadOnly) { beginSlowTxnWithDefaultTxnNumber(); runReadOnlyCommit(); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:readOnly,")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:readOnly,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(0, countLogLinesContaining("coordinator:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_TwoPhase) { beginSlowTxnWithDefaultTxnNumber(); runTwoPhaseCommit(); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:twoPhaseCommit,")); - ASSERT_EQUALS(1, countLogLinesContaining("coordinator:")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:twoPhaseCommit,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("coordinator:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_Recovery) { beginSlowRecoverCommitWithDefaultTxnNumber(); runRecoverWithTokenCommit(shard1); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:recoverWithToken,")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:recoverWithToken,")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(0, countLogLinesContaining("numParticipants:")); - ASSERT_EQUALS(0, countLogLinesContaining("coordinator:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("numParticipants:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_EmptyRecovery) { @@ -3320,45 +3323,45 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_ImplicitAbort) { beginSlowTxnWithDefaultTxnNumber(); implicitAbortInProgress(); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countLogLinesContaining("abortCause:" + kDummyStatus.codeString())); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("abortCause:" + kDummyStatus.codeString())); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); - ASSERT_EQUALS(0, countLogLinesContaining("commitType:")); - ASSERT_EQUALS(0, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitType:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitDurationMicros:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_ExplicitAbort) { beginSlowTxnWithDefaultTxnNumber(); explicitAbortInProgress(); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countLogLinesContaining("abortCause:abort")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("abortCause:abort")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); - ASSERT_EQUALS(0, countLogLinesContaining("commitType:")); - ASSERT_EQUALS(0, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitType:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitDurationMicros:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_SuccessfulCommit) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:committed")); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:singleShard")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:committed")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleShard")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_FailedCommit) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyErrorRes); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countLogLinesContaining("abortCause:" + kDummyStatus.codeString())); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(1, countLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("abortCause:" + kDummyStatus.codeString())); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); } // @@ -3470,9 +3473,9 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Success retryCommit(kDummyOkRes); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:committed")); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:committed")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Abort) { @@ -3483,9 +3486,9 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Abort) retryCommit(kDummyErrorRes); - ASSERT_EQUALS(1, countLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countLogLinesContaining("commitType:")); - ASSERT_EQUALS(1, countLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); } TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Unknown) { diff --git a/src/mongo/unittest/unittest.cpp b/src/mongo/unittest/unittest.cpp index 279b2d07c07..0fc1d57cf5e 100644 --- a/src/mongo/unittest/unittest.cpp +++ b/src/mongo/unittest/unittest.cpp @@ -33,6 +33,7 @@ #include "mongo/unittest/unittest.h" +#include <boost/log/core.hpp> #include <fmt/format.h> #include <fmt/printf.h> #include <functional> @@ -48,6 +49,12 @@ #include "mongo/logger/logger.h" #include "mongo/logger/message_event_utf8_encoder.h" #include "mongo/logger/message_log_domain.h" +#include "mongo/logv2/component_settings_filter.h" +#include "mongo/logv2/log_capture_backend.h" +#include "mongo/logv2/log_domain.h" +#include "mongo/logv2/log_domain_global.h" +#include "mongo/logv2/log_manager.h" +#include "mongo/logv2/plain_formatter.h" #include "mongo/platform/mutex.h" #include "mongo/util/assert_util.h" #include "mongo/util/log.h" @@ -187,13 +194,30 @@ struct UnitTestEnvironment { } // namespace -Test::Test() : _isCapturingLogMessages(false) {} - -Test::~Test() { - if (_isCapturingLogMessages) { - stopCapturingLogMessages(); +class Test::CaptureLogs { +public: + ~CaptureLogs() { + if (_isCapturingLogMessages) { + stopCapturingLogMessages(); + } } -} + void startCapturingLogMessages(); + void stopCapturingLogMessages(); + const std::vector<std::string>& getCapturedTextFormatLogMessages() const; + int64_t countTextFormatLogLinesContaining(const std::string& needle); + void printCapturedTextFormatLogLines() const; + +private: + bool _isCapturingLogMessages{false}; + std::vector<std::string> _capturedLogMessages; + logger::MessageLogDomain::AppenderHandle _captureAppenderHandle; + std::unique_ptr<logger::MessageLogDomain::EventAppender> _captureAppender; + boost::shared_ptr<boost::log::sinks::synchronous_sink<logv2::LogCaptureBackend>> _captureSink; +}; + +Test::Test() : _captureLogs(std::make_unique<CaptureLogs>()) {} + +Test::~Test() {} void Test::run() { UnitTestEnvironment environment(this); @@ -246,38 +270,77 @@ private: }; } // namespace -void Test::startCapturingLogMessages() { +void Test::CaptureLogs::startCapturingLogMessages() { invariant(!_isCapturingLogMessages); _capturedLogMessages.clear(); - if (!_captureAppender) { - _captureAppender = std::make_unique<StringVectorAppender>(&_capturedLogMessages); + + if (logV2Enabled()) { + if (!_captureSink) { + _captureSink = logv2::LogCaptureBackend::create(_capturedLogMessages); + _captureSink->set_filter( + logv2::AllLogsFilter(logv2::LogManager::global().getGlobalDomain())); + _captureSink->set_formatter(logv2::PlainFormatter()); + } + boost::log::core::get()->add_sink(_captureSink); + } else { + if (!_captureAppender) { + _captureAppender = std::make_unique<StringVectorAppender>(&_capturedLogMessages); + } + checked_cast<StringVectorAppender*>(_captureAppender.get())->enable(); + _captureAppenderHandle = + logger::globalLogDomain()->attachAppender(std::move(_captureAppender)); } - checked_cast<StringVectorAppender*>(_captureAppender.get())->enable(); - _captureAppenderHandle = logger::globalLogDomain()->attachAppender(std::move(_captureAppender)); + _isCapturingLogMessages = true; } -void Test::stopCapturingLogMessages() { +void Test::CaptureLogs::stopCapturingLogMessages() { invariant(_isCapturingLogMessages); - invariant(!_captureAppender); - _captureAppender = logger::globalLogDomain()->detachAppender(_captureAppenderHandle); - checked_cast<StringVectorAppender*>(_captureAppender.get())->disable(); + if (logV2Enabled()) { + boost::log::core::get()->remove_sink(_captureSink); + } else { + invariant(!_captureAppender); + _captureAppender = logger::globalLogDomain()->detachAppender(_captureAppenderHandle); + checked_cast<StringVectorAppender*>(_captureAppender.get())->disable(); + } + _isCapturingLogMessages = false; } -void Test::printCapturedLogLines() const { + +const std::vector<std::string>& Test::CaptureLogs::getCapturedTextFormatLogMessages() const { + return _capturedLogMessages; +} + +void Test::CaptureLogs::printCapturedTextFormatLogLines() const { log() << "****************************** Captured Lines (start) *****************************"; - for (const auto& line : getCapturedLogMessages()) { + for (const auto& line : getCapturedTextFormatLogMessages()) { log() << line; } log() << "****************************** Captured Lines (end) ******************************"; } -int64_t Test::countLogLinesContaining(const std::string& needle) { - const auto& msgs = getCapturedLogMessages(); +int64_t Test::CaptureLogs::countTextFormatLogLinesContaining(const std::string& needle) { + const auto& msgs = getCapturedTextFormatLogMessages(); return std::count_if( msgs.begin(), msgs.end(), [&](const std::string& s) { return stringContains(s, needle); }); } +void Test::startCapturingLogMessages() { + _captureLogs->startCapturingLogMessages(); +} +void Test::stopCapturingLogMessages() { + _captureLogs->stopCapturingLogMessages(); +} +const std::vector<std::string>& Test::getCapturedTextFormatLogMessages() const { + return _captureLogs->getCapturedTextFormatLogMessages(); +} +int64_t Test::countTextFormatLogLinesContaining(const std::string& needle) { + return _captureLogs->countTextFormatLogLinesContaining(needle); +} +void Test::printCapturedTextFormatLogLines() const { + _captureLogs->printCapturedTextFormatLogLines(); +} + Suite::Suite(ConstructorEnable, std::string name) : _name(std::move(name)) {} void Suite::add(std::string name, std::string fileName, std::function<void()> testFn) { diff --git a/src/mongo/unittest/unittest.h b/src/mongo/unittest/unittest.h index ebd63872978..30ff41a6971 100644 --- a/src/mongo/unittest/unittest.h +++ b/src/mongo/unittest/unittest.h @@ -569,19 +569,17 @@ protected: * Gets a vector of strings, one log line per string, captured since * the last call to startCapturingLogMessages() in this test. */ - const std::vector<std::string>& getCapturedLogMessages() const { - return _capturedLogMessages; - } + const std::vector<std::string>& getCapturedTextFormatLogMessages() const; /** * Returns the number of collected log lines containing "needle". */ - int64_t countLogLinesContaining(const std::string& needle); + int64_t countTextFormatLogLinesContaining(const std::string& needle); /** * Prints the captured log lines. */ - void printCapturedLogLines() const; + void printCapturedTextFormatLogLines() const; private: /** @@ -589,10 +587,9 @@ private: */ virtual void _doTest() = 0; - bool _isCapturingLogMessages; - std::vector<std::string> _capturedLogMessages; - logger::MessageLogDomain::AppenderHandle _captureAppenderHandle; - std::unique_ptr<logger::MessageLogDomain::EventAppender> _captureAppender; + + class CaptureLogs; + std::unique_ptr<CaptureLogs> _captureLogs; }; /** |