diff options
author | Mark Benvenuto <mark.benvenuto@mongodb.com> | 2020-03-02 22:11:36 -0500 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2020-03-03 03:29:45 +0000 |
commit | 6580304d0211f406566514ec68d5865a6a9e7810 (patch) | |
tree | 22b9d1710b387e9e880f96a26b4315c6f52ed049 /src | |
parent | 33ba055bad586903038902825c14948038ad495e (diff) | |
download | mongo-6580304d0211f406566514ec68d5865a6a9e7810.tar.gz |
SERVER-46219 Unittests should log with JSON format
Diffstat (limited to 'src')
-rw-r--r-- | src/mongo/db/curop.cpp | 19 | ||||
-rw-r--r-- | src/mongo/db/curop.h | 1 | ||||
-rw-r--r-- | src/mongo/db/repl/oplog_applier_impl.cpp | 35 | ||||
-rw-r--r-- | src/mongo/db/repl/oplog_applier_impl_test.cpp | 16 | ||||
-rw-r--r-- | src/mongo/db/repl/vote_requester.cpp | 10 | ||||
-rw-r--r-- | src/mongo/db/repl/vote_requester_test.cpp | 124 | ||||
-rw-r--r-- | src/mongo/db/s/transaction_coordinator.cpp | 142 | ||||
-rw-r--r-- | src/mongo/db/s/transaction_coordinator_test.cpp | 89 | ||||
-rw-r--r-- | src/mongo/db/transaction_participant.cpp | 115 | ||||
-rw-r--r-- | src/mongo/db/transaction_participant.h | 17 | ||||
-rw-r--r-- | src/mongo/db/transaction_participant_test.cpp | 223 | ||||
-rw-r--r-- | src/mongo/logv2/bson_formatter.cpp | 8 | ||||
-rw-r--r-- | src/mongo/s/transaction_router.cpp | 16 | ||||
-rw-r--r-- | src/mongo/s/transaction_router_test.cpp | 171 | ||||
-rw-r--r-- | src/mongo/unittest/unittest.cpp | 79 | ||||
-rw-r--r-- | src/mongo/unittest/unittest.h | 16 |
16 files changed, 761 insertions, 320 deletions
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index 9824e70a766..1c20a27daea 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -496,10 +496,6 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx, logv2::DynamicAttributes attr; _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr), &attr); LOGV2(51803, "slow query", attr); - - // TODO SERVER-46219: Log also with old log system to not break unit tests - log(logComponentV2toV1(component)) - << _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr)); } // Return 'true' if this operation should also be added to the profiler. @@ -1265,4 +1261,19 @@ void OpDebug::AdditiveMetrics::report(logv2::DynamicAttributes* pAttrs) const { OPDEBUG_TOATTR_HELP_ATOMIC("writeConflicts", writeConflicts); } +BSONObj OpDebug::AdditiveMetrics::reportBSON() const { + BSONObjBuilder b; + OPDEBUG_APPEND_OPTIONAL("keysExamined", keysExamined); + OPDEBUG_APPEND_OPTIONAL("docsExamined", docsExamined); + OPDEBUG_APPEND_OPTIONAL("nMatched", nMatched); + OPDEBUG_APPEND_OPTIONAL("nModified", nModified); + OPDEBUG_APPEND_OPTIONAL("ninserted", ninserted); + OPDEBUG_APPEND_OPTIONAL("ndeleted", ndeleted); + OPDEBUG_APPEND_OPTIONAL("keysInserted", keysInserted); + OPDEBUG_APPEND_OPTIONAL("keysDeleted", keysDeleted); + OPDEBUG_APPEND_ATOMIC("prepareReadConflicts", prepareReadConflicts); + OPDEBUG_APPEND_ATOMIC("writeConflicts", writeConflicts); + return b.obj(); +} + } // namespace mongo diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h index 076bc119d75..dc60bd37a86 100644 --- a/src/mongo/db/curop.h +++ b/src/mongo/db/curop.h @@ -122,6 +122,7 @@ public: * the format: "<field1>:<value1> <field2>:<value2> ...". */ std::string report() const; + BSONObj reportBSON() const; void report(logv2::DynamicAttributes* pAttrs) const; diff --git a/src/mongo/db/repl/oplog_applier_impl.cpp b/src/mongo/db/repl/oplog_applier_impl.cpp index bda68314dfc..eb44ffda308 100644 --- a/src/mongo/db/repl/oplog_applier_impl.cpp +++ b/src/mongo/db/repl/oplog_applier_impl.cpp @@ -113,38 +113,19 @@ Status finishAndLogApply(OperationContext* opCtx, Milliseconds(opDuration), Milliseconds(serverGlobalParams.slowMS)) .first) { - { - logv2::DynamicAttributes attrs; + logv2::DynamicAttributes attrs; - auto redacted = redact(entryOrGroupedInserts.toBSON()); - if (entryOrGroupedInserts.getOp().getOpType() == OpTypeEnum::kCommand) { - attrs.add("command", redacted); - } else { - attrs.add("CRUD", redacted); - } - - attrs.add("duration", opDuration); - - LOGV2(51801, "applied op", attrs); + auto redacted = redact(entryOrGroupedInserts.toBSON()); + if (entryOrGroupedInserts.getOp().getOpType() == OpTypeEnum::kCommand) { + attrs.add("command", redacted); + } else { + attrs.add("CRUD", redacted); } - // TODO SERVER-46219: Log also with old log system to not break unit tests - { - StringBuilder s; - s << "applied op: "; + attrs.add("duration", Milliseconds(opDuration)); - if (entryOrGroupedInserts.getOp().getOpType() == OpTypeEnum::kCommand) { - s << "command "; - } else { - s << "CRUD "; - } - - s << redact(entryOrGroupedInserts.toBSON()); - s << ", took " << opDuration << "ms"; - - LOGV2(21228, "{msg}", "msg"_attr = s.str()); - } + LOGV2(51801, "applied op", attrs); } } return finalStatus; diff --git a/src/mongo/db/repl/oplog_applier_impl_test.cpp b/src/mongo/db/repl/oplog_applier_impl_test.cpp index 6f0c8ae14f8..e097ed0192f 100644 --- a/src/mongo/db/repl/oplog_applier_impl_test.cpp +++ b/src/mongo/db/repl/oplog_applier_impl_test.cpp @@ -2240,13 +2240,15 @@ TEST_F(OplogApplierImplTest, LogSlowOpApplicationWhenSuccessful) { ASSERT_OK(_applyOplogEntryOrGroupedInsertsWrapper( _opCtx.get(), &entry, OplogApplication::Mode::kSecondary)); - // Use a builder for easier escaping. We expect the operation to be logged. - StringBuilder expected; - expected << "applied op: CRUD { ts: Timestamp(1, 1), t: 1, v: 2, op: \"i\", ns: \"test.t\", " - "wall: new Date(0), o: " - "{ _id: 0 } }, took " - << applyDuration << "ms"; - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expected.str())); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("CRUD" << BSON("ts" << Timestamp(1, 1) << "t" << 1 << "v" << 2 << "op" + << "i" + << "ns" + << "test.t" + << "wall" << Date_t::fromMillisSinceEpoch(0)) + << "durationMillis" << applyDuration)))); } TEST_F(OplogApplierImplTest, DoNotLogSlowOpApplicationWhenFailed) { diff --git a/src/mongo/db/repl/vote_requester.cpp b/src/mongo/db/repl/vote_requester.cpp index 27b79ca43bb..0349c43334e 100644 --- a/src/mongo/db/repl/vote_requester.cpp +++ b/src/mongo/db/repl/vote_requester.cpp @@ -133,11 +133,8 @@ void VoteRequester::Algorithm::processResponse(const RemoteCommandRequest& reque logAttrs.add("term", _term); logAttrs.add("dryRun", _dryRun); - auto logLine = log(); - logLine << "VoteRequester(term " << _term << (_dryRun ? " dry run" : "") << ") "; _responsesProcessed++; if (!response.isOK()) { // failed response - logLine << "failed to receive response from " << request.target << ": " << response.status; logAttrs.add("failReason", "failed to receive response"_sd); logAttrs.add("error", response.status); logAttrs.add("from", request.target); @@ -155,8 +152,6 @@ void VoteRequester::Algorithm::processResponse(const RemoteCommandRequest& reque status = voteResponse.initialize(response.data); } if (!status.isOK()) { - logLine << "received an invalid response from " << request.target << ": " << status; - logLine << "; response message: " << response.data; logAttrs.add("failReason", "received an invalid response"_sd); logAttrs.add("error", status); logAttrs.add("from", request.target); @@ -165,7 +160,6 @@ void VoteRequester::Algorithm::processResponse(const RemoteCommandRequest& reque } if (voteResponse.getVoteGranted()) { - logLine << "received a yes vote from " << request.target; logAttrs.add("vote", "yes"_sd); logAttrs.add("from", request.target); if (_primaryHost == request.target) { @@ -173,8 +167,6 @@ void VoteRequester::Algorithm::processResponse(const RemoteCommandRequest& reque } _votes++; } else { - logLine << "received a no vote from " << request.target << " with reason \"" - << voteResponse.getReason() << '"'; logAttrs.add("vote", "no"_sd); logAttrs.add("from", request.target); logAttrs.add("reason", voteResponse.getReason()); @@ -183,7 +175,7 @@ void VoteRequester::Algorithm::processResponse(const RemoteCommandRequest& reque if (voteResponse.getTerm() > _term) { _staleTerm = true; } - logLine << "; response message: " << response.data; + logAttrs.add("message", response.data); } diff --git a/src/mongo/db/repl/vote_requester_test.cpp b/src/mongo/db/repl/vote_requester_test.cpp index 94ba342ca11..b5155003603 100644 --- a/src/mongo/db/repl/vote_requester_test.cpp +++ b/src/mongo/db/repl/vote_requester_test.cpp @@ -284,7 +284,13 @@ TEST_F(VoteRequesterTest, VoterFailedToStoreLastVote) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedYesStatusNotOkBecauseFailedToStoreLastVote()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received an invalid response from host1:27017")); + + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("failReason" + << "received an invalid response" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -297,7 +303,11 @@ TEST_F(VoteRequesterTest, BadConfigVersionWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseConfigVersionDoesNotMatch()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -310,7 +320,11 @@ TEST_F(VoteRequesterTest, SetNameDiffersWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseSetNameDiffers()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -323,7 +337,12 @@ TEST_F(VoteRequesterTest, LastOpTimeIsGreaterWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseLastOpTimeIsGreater()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); + processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -336,7 +355,13 @@ TEST_F(VoteRequesterTest, FailedToContactWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), badRemoteCommandResponse()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("failed to receive response from host1:27017")); + + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("failReason" + << "failed to receive response" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -349,7 +374,11 @@ TEST_F(VoteRequesterTest, AlreadyVotedWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseAlreadyVoted()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -361,7 +390,11 @@ TEST_F(VoteRequesterTest, StaleTermLoseElection) { startCapturingLogMessages(); ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseTermIsGreater()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kStaleTerm == getResult()); ASSERT_EQUALS(1, getNumResponders()); @@ -373,9 +406,19 @@ TEST_F(VoteRequesterTest, NotEnoughVotesLoseElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseSetNameDiffers()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), badRemoteCommandResponse()); - ASSERT_EQUALS(1, countLogLinesContaining("failed to receive response from host2:27017")); + + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("failReason" + << "failed to receive response" + << "from" + << "host2:27017")))); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kInsufficientVotes == getResult()); ASSERT_EQUALS(1, getNumResponders()); @@ -387,9 +430,18 @@ TEST_F(VoteRequesterTest, CallbackCanceledNotEnoughVotesLoseElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseAlreadyVoted()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), callbackCanceledCommandResponse()); - ASSERT_EQUALS(1, countLogLinesContaining("failed to receive response from host2:27017")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("failReason" + << "failed to receive response" + << "from" + << "host2:27017")))); // Make sure processing the callbackCanceled Response was necessary to get sufficient responses. ASSERT_TRUE(hasReceivedSufficientResponses()); // Because of the CallbackCanceled Response, host2 doesn't count as a responder. @@ -411,7 +463,11 @@ TEST_F(VoteRequesterDryRunTest, BadConfigVersionWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseConfigVersionDoesNotMatch()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -424,7 +480,11 @@ TEST_F(VoteRequesterDryRunTest, SetNameDiffersWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseSetNameDiffers()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -437,7 +497,11 @@ TEST_F(VoteRequesterDryRunTest, LastOpTimeIsGreaterWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseLastOpTimeIsGreater()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -450,7 +514,6 @@ TEST_F(VoteRequesterDryRunTest, FailedToContactWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), badRemoteCommandResponse()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("failed to receive response from host1:27017")); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -463,7 +526,11 @@ TEST_F(VoteRequesterDryRunTest, AlreadyVotedWinElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseAlreadyVoted()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), votedYes()); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kSuccessfullyElected == getResult()); @@ -475,7 +542,11 @@ TEST_F(VoteRequesterDryRunTest, StaleTermLoseElection) { startCapturingLogMessages(); ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseTermIsGreater()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kStaleTerm == getResult()); ASSERT_EQUALS(1, getNumResponders()); @@ -487,9 +558,18 @@ TEST_F(VoteRequesterDryRunTest, NotEnoughVotesLoseElection) { ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseSetNameDiffers()); ASSERT_FALSE(hasReceivedSufficientResponses()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); processResponse(requestFrom("host2"), badRemoteCommandResponse()); - ASSERT_EQUALS(1, countLogLinesContaining("failed to receive response from host2:27017")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("failReason" + << "failed to receive response" + << "from" + << "host2:27017")))); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kInsufficientVotes == getResult()); ASSERT_EQUALS(1, getNumResponders()); @@ -532,7 +612,11 @@ TEST_F(VoteRequesterCatchupTakeoverDryRunTest, CatchupTakeoverPrimarySaysNoLoseE ASSERT_FALSE(hasReceivedSufficientResponses()); processResponse(requestFrom("host1"), votedNoBecauseLastOpTimeIsGreater()); - ASSERT_EQUALS(1, countLogLinesContaining("received a no vote from host1:27017")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("vote" + << "no" + << "from" + << "host1:27017")))); ASSERT_TRUE(hasReceivedSufficientResponses()); ASSERT(VoteRequester::Result::kPrimaryRespondedNo == getResult()); ASSERT_EQUALS(3, getNumResponders()); diff --git a/src/mongo/db/s/transaction_coordinator.cpp b/src/mongo/db/s/transaction_coordinator.cpp index 94cc02a01fa..712c3b5c325 100644 --- a/src/mongo/db/s/transaction_coordinator.cpp +++ b/src/mongo/db/s/transaction_coordinator.cpp @@ -421,83 +421,71 @@ void TransactionCoordinator::_done(Status status) { void TransactionCoordinator::_logSlowTwoPhaseCommit( const txn::CoordinatorCommitDecision& decision) { - { - logv2::DynamicAttributes attrs; - - BSONObjBuilder parametersBuilder; - - BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid")); - _lsid.serialize(&lsidBuilder); - lsidBuilder.doneFast(); - - parametersBuilder.append("txnNumber", _txnNumber); - - attrs.add("parameters", parametersBuilder.obj()); - - std::string decisionTemp; - switch (decision.getDecision()) { - case txn::CommitDecision::kCommit: - attrs.add("terminationCause", "committed"); - decisionTemp = decision.getCommitTimestamp()->toString(); - attrs.add("commitTimestamp", decisionTemp); - break; - case txn::CommitDecision::kAbort: - attrs.add("terminationCause", "aborted"); - attrs.add("terminationDetails", *decision.getAbortStatus()); - break; - default: - MONGO_UNREACHABLE; - }; - - attrs.add("numParticipants", _participants->size()); - - auto tickSource = _serviceContext->getTickSource(); - auto curTick = tickSource->getTicks(); - const auto& singleTransactionCoordinatorStats = - _transactionCoordinatorMetricsObserver->getSingleTransactionCoordinatorStats(); - - BSONObjBuilder stepDurations; - stepDurations.append( - "writingParticipantListMicros", - durationCount<Microseconds>( - singleTransactionCoordinatorStats.getWritingParticipantListDuration(tickSource, - curTick))); - stepDurations.append( - "waitingForVotesMicros", - durationCount<Microseconds>( - singleTransactionCoordinatorStats.getWaitingForVotesDuration(tickSource, curTick))); - stepDurations.append( - "writingDecisionMicros", - durationCount<Microseconds>( - singleTransactionCoordinatorStats.getWritingDecisionDuration(tickSource, curTick))); - stepDurations.append( - "waitingForDecisionAcksMicros", - durationCount<Microseconds>( - singleTransactionCoordinatorStats.getWaitingForDecisionAcksDuration(tickSource, - curTick))); - stepDurations.append( - "deletingCoordinatorDocMicros", - durationCount<Microseconds>( - singleTransactionCoordinatorStats.getDeletingCoordinatorDocDuration(tickSource, - curTick))); - attrs.add("stepDurations", stepDurations.obj()); - - // Total duration of the commit coordination. Logged at the end of the line for consistency - // with slow command logging. Note that this is reported in milliseconds while the step - // durations are reported in microseconds. - attrs.add( - "duration", - duration_cast<Milliseconds>( - singleTransactionCoordinatorStats.getTwoPhaseCommitDuration(tickSource, curTick))); - - LOGV2(51804, "two-phase commit", attrs); - } - // TODO SERVER-46219: Log also with old log system to not break unit tests - { - LOGV2(22448, - "{twoPhaseCommitInfoForLog_decision}", - "twoPhaseCommitInfoForLog_decision"_attr = _twoPhaseCommitInfoForLog(decision)); - } + logv2::DynamicAttributes attrs; + + BSONObjBuilder parametersBuilder; + + BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid")); + _lsid.serialize(&lsidBuilder); + lsidBuilder.doneFast(); + + parametersBuilder.append("txnNumber", _txnNumber); + + attrs.add("parameters", parametersBuilder.obj()); + + std::string decisionTemp; + switch (decision.getDecision()) { + case txn::CommitDecision::kCommit: + attrs.add("terminationCause", "committed"); + attrs.add("commitTimestamp", decision.getCommitTimestamp()->toBSON()); + break; + case txn::CommitDecision::kAbort: + attrs.add("terminationCause", "aborted"); + attrs.add("terminationDetails", *decision.getAbortStatus()); + break; + default: + MONGO_UNREACHABLE; + }; + + attrs.add("numParticipants", _participants->size()); + + auto tickSource = _serviceContext->getTickSource(); + auto curTick = tickSource->getTicks(); + const auto& singleTransactionCoordinatorStats = + _transactionCoordinatorMetricsObserver->getSingleTransactionCoordinatorStats(); + + BSONObjBuilder stepDurations; + stepDurations.append("writingParticipantListMicros", + durationCount<Microseconds>( + singleTransactionCoordinatorStats.getWritingParticipantListDuration( + tickSource, curTick))); + stepDurations.append( + "waitingForVotesMicros", + durationCount<Microseconds>( + singleTransactionCoordinatorStats.getWaitingForVotesDuration(tickSource, curTick))); + stepDurations.append( + "writingDecisionMicros", + durationCount<Microseconds>( + singleTransactionCoordinatorStats.getWritingDecisionDuration(tickSource, curTick))); + stepDurations.append("waitingForDecisionAcksMicros", + durationCount<Microseconds>( + singleTransactionCoordinatorStats.getWaitingForDecisionAcksDuration( + tickSource, curTick))); + stepDurations.append("deletingCoordinatorDocMicros", + durationCount<Microseconds>( + singleTransactionCoordinatorStats.getDeletingCoordinatorDocDuration( + tickSource, curTick))); + attrs.add("stepDurations", stepDurations.obj()); + + // Total duration of the commit coordination. Logged at the end of the line for consistency + // with slow command logging. Note that this is reported in milliseconds while the step + // durations are reported in microseconds. + attrs.add( + "duration", + duration_cast<Milliseconds>( + singleTransactionCoordinatorStats.getTwoPhaseCommitDuration(tickSource, curTick))); + + LOGV2(51804, "two-phase commit", attrs); } std::string TransactionCoordinator::_twoPhaseCommitInfoForLog( diff --git a/src/mongo/db/s/transaction_coordinator_test.cpp b/src/mongo/db/s/transaction_coordinator_test.cpp index 3f32fb09691..a7d4bd9928f 100644 --- a/src/mongo/db/s/transaction_coordinator_test.cpp +++ b/src/mongo/db/s/transaction_coordinator_test.cpp @@ -1535,7 +1535,7 @@ TEST_F(TransactionCoordinatorMetricsTest, SimpleTwoPhaseCommitRealCoordinator) { checkMetrics(expectedMetrics); LOGV2(22456, - "Start two-phase commit (allow the coordinator to progress to writing the participant " + "Start two phase commit (allow the coordinator to progress to writing the participant " "list)."); expectedStats.writingParticipantListStartTime = advanceClockSourceAndReturnNewNow(); @@ -1680,7 +1680,7 @@ TEST_F(TransactionCoordinatorMetricsTest, SimpleTwoPhaseCommitRealCoordinator) { stopCapturingLogMessages(); // Slow log line is logged since the coordination completed successfully. - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorIsCanceledWhileInactive) { @@ -1725,7 +1725,7 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorIsCanceledWhileInactive) { stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordinatorIsInactive) { @@ -1768,7 +1768,7 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordina stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1829,7 +1829,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1894,7 +1894,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -1961,7 +1961,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, @@ -2032,7 +2032,7 @@ TEST_F(TransactionCoordinatorMetricsTest, stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordinatorIsDeletingDoc) { @@ -2109,19 +2109,19 @@ TEST_F(TransactionCoordinatorMetricsTest, CoordinatorsAWSIsShutDownWhileCoordina stopCapturingLogMessages(); // Slow log line is not logged since the coordination did not complete successfully. - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionAtLogLevelOne) { setMinimumLoggedSeverity(logv2::LogComponent::kTransaction, logv2::LogSeverity::Debug(1)); runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionAtLogLevelZero) { setMinimumLoggedSeverity(logv2::LogComponent::kTransaction, logv2::LogSeverity::Log()); runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionsUnderSlowMSThreshold) { @@ -2150,7 +2150,7 @@ TEST_F(TransactionCoordinatorMetricsTest, DoesNotLogTransactionsUnderSlowMSThres coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F( @@ -2181,7 +2181,7 @@ TEST_F( coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionsOverSlowMSThreshold) { @@ -2210,7 +2210,7 @@ TEST_F(TransactionCoordinatorMetricsTest, LogsTransactionsOverSlowMSThreshold) { coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("two-phase commit")); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTransactionParameters) { @@ -2218,17 +2218,19 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTransactionParamete BSONObjBuilder lsidBob; _lsid.serialize(&lsidBob); ASSERT_EQUALS(1, - countTextFormatLogLinesContaining( - str::stream() << "parameters:{ lsid: " << lsidBob.done().toString() - << ", txnNumber: " << _txnNumber)); + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("parameters" << BSON("lsid" << lsidBob.obj() << "txnNumber" + << _txnNumber))))); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseAndCommitTimestampForCommitDecision) { runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); ASSERT_EQUALS(1, - countTextFormatLogLinesContaining( - "terminationCause:committed, commitTimestamp: Timestamp(1, 1)")); + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("terminationCause" + << "committed" + << "commitTimestamp" << Timestamp(1, 1).toBSON())))); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseForAbortDecision) { @@ -2251,17 +2253,34 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesTerminationCauseFor coordinator.onCompletion().get(); stopCapturingLogMessages(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("terminationCause" + << "aborted")))); + ASSERT_EQUALS( 1, - countTextFormatLogLinesContaining("terminationDetails: NoSuchTransaction: from shard s1") + - countTextFormatLogLinesContaining( - "terminationDetails: NoSuchTransaction: from shard s2")); + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON( + "terminationDetails" + << BSON("code" << 251 << "codeName" + << "NoSuchTransaction" + << "errmsg" + << "from shard s1 :: caused by :: No such transaction exists")))) + + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON( + "terminationDetails" + << BSON("code" << 251 << "codeName" + << "NoSuchTransaction" + << "errmsg" + << "from shard s2 :: caused by :: No such transaction exists")))) + + ); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesNumParticipants) { runSimpleTwoPhaseCommitWithCommitDecisionAndCaptureLogLines(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); + + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("numParticipants" << 2)))); } TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesStepDurationsAndTotalDuration) { @@ -2336,16 +2355,18 @@ TEST_F(TransactionCoordinatorMetricsTest, SlowLogLineIncludesStepDurationsAndTot stopCapturingLogMessages(); // Note: The waiting for decision acks and deleting coordinator doc durations are not reported. - ASSERT_EQUALS(1, - 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"); - })); + + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("stepDurations" << BSON( + + "writingParticipantListMicros" + << 100000 << "waitingForVotesMicros" << 100000 + << "writingDecisionMicros" << 100000 + << "waitingForDecisionAcksMicros" << 100000 + << "deletingCoordinatorDocMicros" << 100000) + << "durationMillis" << 500)))); } TEST_F(TransactionCoordinatorMetricsTest, ServerStatusSectionIncludesTotalCreated) { diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp index c0737906754..10b5cb15004 100644 --- a/src/mongo/db/transaction_participant.cpp +++ b/src/mongo/db/transaction_participant.cpp @@ -1943,19 +1943,15 @@ void TransactionParticipant::Participant::_transactionInfoForLog( singleTransactionStats.getOpDebug()->additiveMetrics.report(pAttrs); - std::string terminationCauseString = + StringData terminationCauseString = terminationCause == TerminationCause::kCommitted ? "committed" : "aborted"; pAttrs->add("terminationCause", terminationCauseString); auto tickSource = opCtx->getServiceContext()->getTickSource(); auto curTick = tickSource->getTicks(); - pAttrs->add("timeActive", - durationCount<Microseconds>( - singleTransactionStats.getTimeActiveMicros(tickSource, curTick))); - pAttrs->add("timeInactive", - durationCount<Microseconds>( - singleTransactionStats.getTimeInactiveMicros(tickSource, curTick))); + pAttrs->add("timeActive", singleTransactionStats.getTimeActiveMicros(tickSource, curTick)); + pAttrs->add("timeInactive", singleTransactionStats.getTimeInactiveMicros(tickSource, curTick)); // Number of yields is always 0 in multi-document transactions, but it is included mainly to // match the format with other slow operation logging messages. @@ -1976,7 +1972,7 @@ void TransactionParticipant::Participant::_transactionInfoForLog( const bool txnWasPrepared = totalPreparedDuration > 0; pAttrs->add("wasPrepared", txnWasPrepared); if (txnWasPrepared) { - pAttrs->add("totalPreparedDuration", totalPreparedDuration); + pAttrs->add("totalPreparedDuration", Microseconds(totalPreparedDuration)); pAttrs->add("prepareOpTime", o().prepareOpTime); } @@ -1986,6 +1982,83 @@ void TransactionParticipant::Participant::_transactionInfoForLog( duration_cast<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick))); } +// Needs to be kept in sync with _transactionInfoForLog +BSONObj TransactionParticipant::Participant::_transactionInfoBSONForLog( + OperationContext* opCtx, + const SingleThreadedLockStats* lockStats, + TerminationCause terminationCause, + repl::ReadConcernArgs readConcernArgs) const { + invariant(lockStats); + + // User specified transaction parameters. + BSONObjBuilder parametersBuilder; + + BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid")); + _sessionId().serialize(&lsidBuilder); + lsidBuilder.doneFast(); + + parametersBuilder.append("txnNumber", o().activeTxnNumber); + parametersBuilder.append("autocommit", p().autoCommit ? *p().autoCommit : true); + readConcernArgs.appendInfo(¶metersBuilder); + + BSONObjBuilder logLine; + { + BSONObjBuilder attrs = logLine.subobjStart("attr"); + attrs.append("parameters", parametersBuilder.obj()); + + const auto& singleTransactionStats = + o().transactionMetricsObserver.getSingleTransactionStats(); + + attrs.append("readTimestamp", singleTransactionStats.getReadTimestamp().toString()); + + attrs.appendElements(singleTransactionStats.getOpDebug()->additiveMetrics.reportBSON()); + + StringData terminationCauseString = + terminationCause == TerminationCause::kCommitted ? "committed" : "aborted"; + attrs.append("terminationCause", terminationCauseString); + + auto tickSource = opCtx->getServiceContext()->getTickSource(); + auto curTick = tickSource->getTicks(); + + attrs.append("timeActiveMicros", + durationCount<Microseconds>( + singleTransactionStats.getTimeActiveMicros(tickSource, curTick))); + attrs.append("timeInactiveMicros", + durationCount<Microseconds>( + singleTransactionStats.getTimeInactiveMicros(tickSource, curTick))); + + // Number of yields is always 0 in multi-document transactions, but it is included mainly to + // match the format with other slow operation logging messages. + attrs.append("numYields", 0); + // Aggregate lock statistics. + + BSONObjBuilder locks; + lockStats->report(&locks); + attrs.append("locks", locks.obj()); + + if (singleTransactionStats.getOpDebug()->storageStats) + attrs.append("storage", singleTransactionStats.getOpDebug()->storageStats->toBSON()); + + // It is possible for a slow transaction to have aborted in the prepared state if an + // exception was thrown before prepareTransaction succeeds. + const auto totalPreparedDuration = durationCount<Microseconds>( + singleTransactionStats.getPreparedDuration(tickSource, curTick)); + const bool txnWasPrepared = totalPreparedDuration > 0; + attrs.append("wasPrepared", txnWasPrepared); + if (txnWasPrepared) { + attrs.append("totalPreparedDurationMicros", totalPreparedDuration); + attrs.append("prepareOpTime", o().prepareOpTime.toBSON()); + } + + // Total duration of the transaction. + attrs.append( + "durationMillis", + duration_cast<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick)) + .count()); + } + return logLine.obj(); +} + void TransactionParticipant::Participant::_logSlowTransaction( OperationContext* opCtx, const SingleThreadedLockStats* lockStats, @@ -2003,20 +2076,9 @@ void TransactionParticipant::Participant::_logSlowTransaction( opDuration, Milliseconds(serverGlobalParams.slowMS)) .first) { - { - logv2::DynamicAttributes attr; - _transactionInfoForLog(opCtx, lockStats, terminationCause, readConcernArgs, &attr); - LOGV2_OPTIONS(51802, {logv2::LogComponent::kTransaction}, "transaction", attr); - } - // TODO SERVER-46219: Log also with old log system to not break unit tests - { - LOGV2_OPTIONS(22523, - {logv2::LogComponent::kTransaction}, - "transaction " - "{transactionInfo}", - "transactionInfo"_attr = _transactionInfoForLog( - opCtx, lockStats, terminationCause, readConcernArgs)); - } + logv2::DynamicAttributes attr; + _transactionInfoForLog(opCtx, lockStats, terminationCause, readConcernArgs, &attr); + LOGV2_OPTIONS(51802, {logv2::LogComponent::kTransaction}, "transaction", attr); } } } @@ -2086,8 +2148,9 @@ void TransactionParticipant::Participant::refreshFromStorageIfNeeded(OperationCo TransactionState::kAbortedWithPrepare, TransactionState::TransitionValidation::kRelaxTransitionValidation); break; - // We should never be refreshing a prepared or in-progress transaction from storage - // since it should already be in a valid state after replication recovery. + // We should never be refreshing a prepared or in-progress transaction from + // storage since it should already be in a valid state after replication + // recovery. case DurableTxnStateEnum::kPrepared: case DurableTxnStateEnum::kInProgress: MONGO_UNREACHABLE; @@ -2161,8 +2224,8 @@ void TransactionParticipant::Participant::_resetRetryableWriteState() { void TransactionParticipant::Participant::_resetTransactionState( WithLock wl, TransactionState::StateFlag state) { // If we are transitioning to kNone, we are either starting a new transaction or aborting a - // prepared transaction for rollback. In the latter case, we will need to relax the invariant - // that prevents transitioning from kPrepared to kNone. + // prepared transaction for rollback. In the latter case, we will need to relax the + // invariant that prevents transitioning from kPrepared to kNone. if (o().txnState.isPrepared() && state == TransactionState::kNone) { o(wl).txnState.transitionTo( state, TransactionState::TransitionValidation::kRelaxTransitionValidation); diff --git a/src/mongo/db/transaction_participant.h b/src/mongo/db/transaction_participant.h index 8bcf69a1f4b..10314d38188 100644 --- a/src/mongo/db/transaction_participant.h +++ b/src/mongo/db/transaction_participant.h @@ -599,6 +599,18 @@ public: return _transactionInfoForLog(opCtx, lockStats, terminationCause, readConcernArgs); } + BSONObj getTransactionInfoBSONForLogForTest( + OperationContext* opCtx, + const SingleThreadedLockStats* lockStats, + bool committed, + const repl::ReadConcernArgs& readConcernArgs) const { + + TerminationCause terminationCause = + committed ? TerminationCause::kCommitted : TerminationCause::kAborted; + return _transactionInfoBSONForLog(opCtx, lockStats, terminationCause, readConcernArgs); + } + + SingleTransactionStats getSingleTransactionStatsForTest() const { return o().transactionMetricsObserver.getSingleTransactionStats(); } @@ -706,6 +718,11 @@ public: repl::ReadConcernArgs readConcernArgs, logv2::DynamicAttributes* pAttrs) const; + BSONObj _transactionInfoBSONForLog(OperationContext* opCtx, + const SingleThreadedLockStats* lockStats, + TerminationCause terminationCause, + repl::ReadConcernArgs readConcernArgs) const; + // Bumps up the transaction number of this transaction and perform the necessary cleanup. void _setNewTxnNumber(OperationContext* opCtx, const TxnNumber& txnNumber); diff --git a/src/mongo/db/transaction_participant_test.cpp b/src/mongo/db/transaction_participant_test.cpp index 61aca5cf9fa..990b1763a70 100644 --- a/src/mongo/db/transaction_participant_test.cpp +++ b/src/mongo/db/transaction_participant_test.cpp @@ -3113,6 +3113,152 @@ std::string buildTransactionInfoString(OperationContext* opCtx, return expectedTransactionInfo.str(); } + +/* + * Builds expected parameters info BSON. + */ +void buildParametersInfoBSON(BSONObjBuilder* builder, + LogicalSessionId sessionId, + const TxnNumber txnNum, + const repl::ReadConcernArgs readConcernArgs, + bool autocommitVal) { + BSONObjBuilder lsidBuilder; + sessionId.serialize(&lsidBuilder); + auto autocommitString = autocommitVal ? "true" : "false"; + + BSONObjBuilder params = builder->subobjStart("parameters"); + params.append("lsid", lsidBuilder.obj()); + params.append("txnNumber", txnNum); + params.append("autocommit", autocommitString); + readConcernArgs.appendInfo(¶ms); +} + +/* + * Builds expected single transaction stats info string. + */ +void buildSingleTransactionStatsBSON(BSONObjBuilder* builder, const int metricValue) { + builder->append("keysExamined", metricValue); + builder->append("docsExamined", metricValue); + builder->append("nMatched", metricValue); + builder->append("nModified", metricValue); + builder->append("ninserted", metricValue); + builder->append("ndeleted", metricValue); + builder->append("keysInserted", metricValue); + builder->append("keysDeleted", metricValue); + builder->append("prepareReadConflicts", metricValue); + builder->append("writeConflicts", metricValue); +} + +/* + * Builds the time active and time inactive info BSON. + */ +void buildTimeActiveInactiveBSON(BSONObjBuilder* builder, + TransactionParticipant::Participant txnParticipant, + TickSource* tickSource, + TickSource::Tick curTick) { + // Add time active micros to string. + builder->append("timeActiveMicros", + durationCount<Microseconds>( + txnParticipant.getSingleTransactionStatsForTest().getTimeActiveMicros( + tickSource, curTick))); + + // Add time inactive micros to string. + builder->append("timeInactiveMicros", + durationCount<Microseconds>( + txnParticipant.getSingleTransactionStatsForTest().getTimeInactiveMicros( + tickSource, curTick))); +} + +/* + * Builds the total prepared duration info BSON. + */ +void buildPreparedDurationBSON(BSONObjBuilder* builder, + TransactionParticipant::Participant txnParticipant, + TickSource* tickSource, + TickSource::Tick curTick) { + builder->append("totalPreparedDurationMicros", + durationCount<Microseconds>( + txnParticipant.getSingleTransactionStatsForTest().getPreparedDuration( + tickSource, curTick))); +} + +/* + * Builds the entire expected transaction info BSON and returns it. + * + * Must be kept in sync with TransactionParticipant::Participant::_transactionInfoForLog. + */ +BSONObj buildTransactionInfoBSON(OperationContext* opCtx, + TransactionParticipant::Participant txnParticipant, + std::string terminationCause, + const LogicalSessionId sessionId, + const TxnNumber txnNum, + const int metricValue, + const bool wasPrepared, + bool autocommitVal = false, + boost::optional<repl::OpTime> prepareOpTime = boost::none) { + // Calling transactionInfoForLog to get the actual transaction info string. + const auto lockerInfo = + opCtx->lockState()->getLockerInfo(CurOp::get(*opCtx)->getLockStatsBase()); + // Building expected transaction info string. + StringBuilder parametersInfo; + // autocommit must be false for a multi statement transaction, so + // getTransactionInfoForLogForTest should theoretically always print false. In certain unit + // tests, we compare its output to the output generated in this function. + // + // Since we clear the state of a transaction on abort, if getTransactionInfoForLogForTest is + // called after a transaction is already aborted, it will encounter boost::none for the + // autocommit value. In that case, it will print out true. + // + // In cases where we call getTransactionInfoForLogForTest after aborting a transaction + // and check if the output matches this function's output, we must explicitly set autocommitVal + // to true. + + BSONObjBuilder logLine; + { + BSONObjBuilder attrs = logLine.subobjStart("attr"); + + buildParametersInfoBSON( + &attrs, sessionId, txnNum, repl::ReadConcernArgs::get(opCtx), autocommitVal); + + + attrs.append( + "readTimestamp", + txnParticipant.getSingleTransactionStatsForTest().getReadTimestamp().toString()); + + buildSingleTransactionStatsBSON(&attrs, metricValue); + + attrs.append("terminationCause", terminationCause); + auto tickSource = opCtx->getServiceContext()->getTickSource(); + buildTimeActiveInactiveBSON(&attrs, txnParticipant, tickSource, tickSource->getTicks()); + + attrs.append("numYields", 0); + + BSONObjBuilder locks; + if (lockerInfo) { + lockerInfo->stats.report(&locks); + } + attrs.append("locks", locks.obj()); + + attrs.append("wasPrepared", wasPrepared); + + if (wasPrepared) { + buildPreparedDurationBSON(&attrs, txnParticipant, tickSource, tickSource->getTicks()); + attrs.append("prepareOpTime", + (prepareOpTime ? prepareOpTime->toBSON() + : txnParticipant.getPrepareOpTime().toBSON())); + } + + attrs.append("durationMillis", + duration_cast<Milliseconds>( + txnParticipant.getSingleTransactionStatsForTest().getDuration( + tickSource, tickSource->getTicks())) + .count()); + } + + return logLine.obj(); +} + + TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterCommit) { // Initialize SingleTransactionStats AdditiveMetrics objects. const int metricValue = 1; @@ -3344,10 +3490,10 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) { const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none); ASSERT(lockerInfo); - std::string expectedTransactionInfo = "transaction " + - txnParticipant.getTransactionInfoForLogForTest( - opCtx(), &lockerInfo->stats, true, readConcernArgs); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + + BSONObj expected = txnParticipant.getTransactionInfoBSONForLogForTest( + opCtx(), &lockerInfo->stats, true, readConcernArgs); + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(expected)); } TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowCommit) { @@ -3392,10 +3538,10 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowCommit) { const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none); ASSERT(lockerInfo); - std::string expectedTransactionInfo = "transaction " + - txnParticipant.getTransactionInfoForLogForTest( - opCtx(), &lockerInfo->stats, true, readConcernArgs); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + + BSONObj expected = txnParticipant.getTransactionInfoBSONForLogForTest( + opCtx(), &lockerInfo->stats, true, readConcernArgs); + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(expected)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { @@ -3440,16 +3586,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none); ASSERT(lockerInfo); - std::string expectedTransactionInfo = - buildTransactionInfoString(opCtx(), - txnParticipant, - "aborted", - *opCtx()->getLogicalSessionId(), - *opCtx()->getTxnNumber(), - metricValue, - false); + auto expectedTransactionInfo = buildTransactionInfoBSON(opCtx(), + txnParticipant, + "aborted", + *opCtx()->getLogicalSessionId(), + *opCtx()->getTxnNumber(), + metricValue, + false); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowAbort) { @@ -3497,18 +3642,16 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowAbort) { const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none); ASSERT(lockerInfo); - std::string expectedTransactionInfo = - buildTransactionInfoString(opCtx(), - txnParticipant, - "aborted", - *opCtx()->getLogicalSessionId(), - *opCtx()->getTxnNumber(), - metricValue, - true, - false, - prepareOpTime); - - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + auto expectedTransactionInfo = buildTransactionInfoBSON(opCtx(), + txnParticipant, + "aborted", + *opCtx()->getLogicalSessionId(), + *opCtx()->getTxnNumber(), + metricValue, + true, + false, + prepareOpTime); + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterExceptionInPrepare) { @@ -3557,16 +3700,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterExceptionInPrepare) { const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none); ASSERT(lockerInfo); - std::string expectedTransactionInfo = - buildTransactionInfoString(opCtx(), - txnParticipant, - "aborted", - *opCtx()->getLogicalSessionId(), - *opCtx()->getTxnNumber(), - metricValue, - false); + auto expectedTransactionInfo = buildTransactionInfoBSON(opCtx(), + txnParticipant, + "aborted", + *opCtx()->getLogicalSessionId(), + *opCtx()->getTxnNumber(), + metricValue, + false); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countBSONFormatLogLinesIsSubset(expectedTransactionInfo)); } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { @@ -3615,8 +3757,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { txnParticipant.abortTransaction(opCtx()); stopCapturingLogMessages(); - std::string expectedTransactionInfo = "transaction parameters"; - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(expectedTransactionInfo)); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction")); } TEST_F(TransactionsMetricsTest, LogTransactionInfoZeroSampleRate) { @@ -3712,7 +3853,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoVerbosityDebug) { setMinimumLoggedSeverity(logv2::LogComponent::kTransaction, logv2::LogSeverity::Info()); // Test that the transaction is still logged. - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction parameters")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction")); } TEST_F(TxnParticipantTest, RollbackResetsInMemoryStateOfPreparedTransaction) { diff --git a/src/mongo/logv2/bson_formatter.cpp b/src/mongo/logv2/bson_formatter.cpp index c80e75af921..88222e6a9d6 100644 --- a/src/mongo/logv2/bson_formatter.cpp +++ b/src/mongo/logv2/bson_formatter.cpp @@ -78,12 +78,12 @@ struct BSONValueExtractor { } // BSONObj is coming as a pointer, the generic one handles references - void operator()(StringData name, const BSONObj* val) { - _builder.append(name, *val); + void operator()(StringData name, const BSONObj val) { + _builder.append(name, val); } - void operator()(StringData name, const BSONArray* val) { - _builder.append(name, *val); + void operator()(StringData name, const BSONArray val) { + _builder.append(name, val); } // BSON is lacking unsigned types, so store unsigned int32 as signed int64 diff --git a/src/mongo/s/transaction_router.cpp b/src/mongo/s/transaction_router.cpp index d6c5f75c733..5d5b2ee0417 100644 --- a/src/mongo/s/transaction_router.cpp +++ b/src/mongo/s/transaction_router.cpp @@ -1333,6 +1333,7 @@ BSONObj TransactionRouter::Router::_commitWithRecoveryToken(OperationContext* op void TransactionRouter::Router::_logSlowTransaction(OperationContext* opCtx, TerminationCause terminationCause) const { + logv2::DynamicAttributes attrs; BSONObjBuilder parametersBuilder; @@ -1390,15 +1391,12 @@ void TransactionRouter::Router::_logSlowTransaction(OperationContext* opCtx, commitTypeTemp = commitTypeToString(o().commitType); attrs.add("commitType", commitTypeTemp); - attrs.add("commitDuration", - durationCount<Microseconds>(timingStats.getCommitDuration(tickSource, curTicks))); + attrs.add("commitDuration", timingStats.getCommitDuration(tickSource, curTicks)); } - attrs.add("timeActive", - durationCount<Microseconds>(timingStats.getTimeActiveMicros(tickSource, curTicks))); + attrs.add("timeActive", timingStats.getTimeActiveMicros(tickSource, curTicks)); - attrs.add("timeInactive", - durationCount<Microseconds>(timingStats.getTimeInactiveMicros(tickSource, curTicks))); + attrs.add("timeInactive", timingStats.getTimeInactiveMicros(tickSource, curTicks)); // Total duration of the transaction. Logged at the end of the line for consistency with // slow command logging. @@ -1406,12 +1404,6 @@ void TransactionRouter::Router::_logSlowTransaction(OperationContext* opCtx, duration_cast<Milliseconds>(timingStats.getDuration(tickSource, curTicks))); LOGV2(51805, "transaction", attrs); - - // TODO SERVER-46219: Log also with old log system to not break unit tests - LOGV2(22899, - "transaction {transactionInfoForLog_opCtx_terminationCause}", - "transactionInfoForLog_opCtx_terminationCause"_attr = - _transactionInfoForLog(opCtx, terminationCause)); } std::string TransactionRouter::Router::_transactionInfoForLog( diff --git a/src/mongo/s/transaction_router_test.cpp b/src/mongo/s/transaction_router_test.cpp index 9b278c445c1..18bc6833570 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, countTextFormatLogLinesContaining("transaction parameters:")); + ASSERT_EQUALS(1, countTextFormatLogLinesContaining("transaction")); } void assertDidNotPrintSlowLogLine() { - ASSERT_EQUALS(0, countTextFormatLogLinesContaining("transaction parameters:")); + ASSERT_EQUALS(0, countTextFormatLogLinesContaining("transaction")); } auto routerTxnMetrics() { @@ -3194,10 +3194,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTransactionParameters) { BSONObjBuilder lsidBob; getSessionId().serialize(&lsidBob); - ASSERT_EQUALS(1, - countTextFormatLogLinesContaining( - str::stream() << "parameters:{ lsid: " << lsidBob.done().toString() - << ", txnNumber: " << kTxnNumber << ", autocommit: false")); + + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("parameters" << BSON("lsid" << lsidBob.obj() << "txnNumber" << kTxnNumber + << "autocommit" << false))))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsDurationAtEnd) { @@ -3205,27 +3207,28 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsDurationAtEnd) { tickSource()->advance(Milliseconds(111)); assertDurationIs(Milliseconds(111)); runCommit(kDummyOkRes); - const auto& logs = getCapturedTextFormatLogMessages(); - ASSERT_EQUALS(1, std::count_if(logs.begin(), logs.end(), [](const std::string& line) { - return StringData(line).endsWith(" 111ms"); - })); + + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("durationMillis" << 111)))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTimeActiveAndInactive) { beginTxnWithDefaultTxnNumber(); - tickSource()->advance(Microseconds(111)); - assertTimeActiveIs(Microseconds(111)); + tickSource()->advance(Microseconds(111111)); + assertTimeActiveIs(Microseconds(111111)); txnRouter().stash(operationContext()); - tickSource()->advance(Microseconds(222)); - assertTimeInactiveIs(Microseconds(222)); + tickSource()->advance(Microseconds(222222)); + assertTimeInactiveIs(Microseconds(222222)); txnRouter().beginOrContinueTxn( operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("timeActiveMicros:111,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("timeInactiveMicros:222,")); + ASSERT_EQUALS( + 1, countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("timeActiveMicros" << 111111)))); + ASSERT_EQUALS( + 1, countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("timeInactiveMicros" << 222222)))); } // @@ -3250,7 +3253,11 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Local) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("parameters" + << BSON("readConcern" << readConcern.toBSON()["readConcern"].Obj()))))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("globalReadTimestamp:")); } @@ -3261,7 +3268,11 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Majority) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("parameters" + << BSON("readConcern" << readConcern.toBSON()["readConcern"].Obj()))))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("globalReadTimestamp:")); } @@ -3272,8 +3283,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingReadConcern_Snapshot) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining(readConcern.toBSON()["readConcern"])); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("globalReadTimestamp:")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("parameters" + << BSON("readConcern" << readConcern.toBSON()["readConcern"].Obj())) + << "globalReadTimestamp" << BSONUndefined))); } // @@ -3284,9 +3299,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_NoShards) { beginSlowTxnWithDefaultTxnNumber(); runNoShardCommit(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:noShards,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:0")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("commitType" + << "noShards" + << "numParticipants" << 0 << "commitDurationMicros" << BSONUndefined)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } @@ -3295,9 +3313,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_SingleShard) { beginSlowTxnWithDefaultTxnNumber(); runSingleShardCommit(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleShard,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("commitType" + << "singleShard" + << "numParticipants" << 1 << "commitDurationMicros" << BSONUndefined)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } @@ -3306,9 +3327,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_SingleWriteShard) { beginSlowTxnWithDefaultTxnNumber(); runSingleWriteShardCommit(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleWriteShard,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("commitType" + << "singleWriteShard" + << "numParticipants" << 2 << "commitDurationMicros" << BSONUndefined)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } @@ -3317,9 +3341,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_ReadOnly) { beginSlowTxnWithDefaultTxnNumber(); runReadOnlyCommit(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:readOnly,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("commitType" + << "readOnly" + << "numParticipants" << 2 << "commitDurationMicros" << BSONUndefined)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); } @@ -3328,18 +3355,23 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_TwoPhase) { beginSlowTxnWithDefaultTxnNumber(); runTwoPhaseCommit(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:twoPhaseCommit,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("coordinator:")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:2")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("commitType" + << "twoPhaseCommit" + << "numParticipants" << 2 << "commitDurationMicros" + << BSONUndefined << "coordinator" << BSONUndefined)))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingCommitType_Recovery) { beginSlowRecoverCommitWithDefaultTxnNumber(); runRecoverWithTokenCommit(shard1); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:recoverWithToken,")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("commitType" + << "recoverWithToken" + << "commitDurationMicros" << BSONUndefined)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("numParticipants:")); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("coordinator:")); @@ -3362,9 +3394,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_ImplicitAbort) { beginSlowTxnWithDefaultTxnNumber(); implicitAbortInProgress(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("abortCause:" + kDummyStatus.codeString())); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("terminationCause" + << "aborted" + << "abortCause" << kDummyStatus.codeString() + << "numParticipants" << 1)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitType:")); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitDurationMicros:")); @@ -3374,9 +3409,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_ExplicitAbort) { beginSlowTxnWithDefaultTxnNumber(); explicitAbortInProgress(); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("abortCause:abort")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset(BSON("attr" << BSON("terminationCause" + << "aborted" + << "abortCause" + << "abort" + << "numParticipants" << 1)))); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitType:")); ASSERT_EQUALS(0, countTextFormatLogLinesContaining("commitDurationMicros:")); @@ -3386,21 +3424,30 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_SuccessfulCommit) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:committed")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:singleShard")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("numParticipants:1")); + ASSERT_EQUALS( + 1, + countBSONFormatLogLinesIsSubset(BSON( + "attr" << BSON("terminationCause" + << "committed" + << "commitType" + << "singleShard" + << "numParticipants" << 1 << "commitDurationMicros" << BSONUndefined)))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingOnTerminate_FailedCommit) { beginSlowTxnWithDefaultTxnNumber(); runCommit(kDummyErrorRes); - 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")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("terminationCause" + << "aborted" + << "abortCause" << kDummyStatus.codeString() + << "numParticipants" << 1 << "commitDurationMicros" + << BSONUndefined << "commitType" << BSONUndefined)))); + + // ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); + // ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); } // @@ -3512,9 +3559,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Success retryCommit(kDummyOkRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:committed")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("terminationCause" + << "committed" + << "commitDurationMicros" << BSONUndefined << "commitType" + << BSONUndefined)))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Abort) { @@ -3525,9 +3575,12 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Abort) retryCommit(kDummyErrorRes); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("terminationCause:aborted")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitType:")); - ASSERT_EQUALS(1, countTextFormatLogLinesContaining("commitDurationMicros:")); + ASSERT_EQUALS(1, + countBSONFormatLogLinesIsSubset( + BSON("attr" << BSON("terminationCause" + << "aborted" + << "commitDurationMicros" << BSONUndefined << "commitType" + << BSONUndefined)))); } TEST_F(TransactionRouterMetricsTest, SlowLoggingAfterUnknownCommitResult_Unknown) { diff --git a/src/mongo/unittest/unittest.cpp b/src/mongo/unittest/unittest.cpp index 5bd0ce6aa61..244086766cb 100644 --- a/src/mongo/unittest/unittest.cpp +++ b/src/mongo/unittest/unittest.cpp @@ -49,6 +49,7 @@ #include "mongo/logger/logger.h" #include "mongo/logger/message_event_utf8_encoder.h" #include "mongo/logger/message_log_domain.h" +#include "mongo/logv2/bson_formatter.h" #include "mongo/logv2/component_settings_filter.h" #include "mongo/logv2/log.h" #include "mongo/logv2/log_capture_backend.h" @@ -207,15 +208,28 @@ public: void startCapturingLogMessages(); void stopCapturingLogMessages(); const std::vector<std::string>& getCapturedTextFormatLogMessages() const; + const std::vector<BSONObj> getCapturedBSONFormatLogMessages() const; int64_t countTextFormatLogLinesContaining(const std::string& needle); + int64_t countBSONFormatLogLinesIsSubset(const BSONObj needle); void printCapturedTextFormatLogLines() const; private: bool _isCapturingLogMessages{false}; + + // Captures Plain Text Log std::vector<std::string> _capturedLogMessages; + + // Captured BSON + std::vector<std::string> _capturedBSONLogMessages; logger::MessageLogDomain::AppenderHandle _captureAppenderHandle; std::unique_ptr<logger::MessageLogDomain::EventAppender> _captureAppender; + + // Capture Sink for Plain Text boost::shared_ptr<boost::log::sinks::synchronous_sink<logv2::LogCaptureBackend>> _captureSink; + + // Capture Sink for BSON + boost::shared_ptr<boost::log::sinks::synchronous_sink<logv2::LogCaptureBackend>> + _captureBSONSink; }; Test::Test() : _captureLogs(std::make_unique<CaptureLogs>()) {} @@ -283,8 +297,15 @@ void Test::CaptureLogs::startCapturingLogMessages() { _captureSink->set_filter( logv2::AllLogsFilter(logv2::LogManager::global().getGlobalDomain())); _captureSink->set_formatter(logv2::PlainFormatter()); + + _captureBSONSink = logv2::LogCaptureBackend::create(_capturedBSONLogMessages); + + _captureBSONSink->set_filter( + logv2::AllLogsFilter(logv2::LogManager::global().getGlobalDomain())); + _captureBSONSink->set_formatter(logv2::BSONFormatter()); } boost::log::core::get()->add_sink(_captureSink); + boost::log::core::get()->add_sink(_captureBSONSink); } else { if (!_captureAppender) { _captureAppender = std::make_unique<StringVectorAppender>(&_capturedLogMessages); @@ -301,6 +322,7 @@ void Test::CaptureLogs::stopCapturingLogMessages() { invariant(_isCapturingLogMessages); if (logV2Enabled()) { boost::log::core::get()->remove_sink(_captureSink); + boost::log::core::get()->remove_sink(_captureBSONSink); } else { invariant(!_captureAppender); _captureAppender = logger::globalLogDomain()->detachAppender(_captureAppenderHandle); @@ -314,6 +336,14 @@ const std::vector<std::string>& Test::CaptureLogs::getCapturedTextFormatLogMessa return _capturedLogMessages; } +const std::vector<BSONObj> Test::CaptureLogs::getCapturedBSONFormatLogMessages() const { + std::vector<BSONObj> objs; + std::transform(_capturedBSONLogMessages.cbegin(), + _capturedBSONLogMessages.cend(), + std::back_inserter(objs), + [](const std::string& str) { return BSONObj(str.c_str()); }); + return objs; +} void Test::CaptureLogs::printCapturedTextFormatLogLines() const { LOGV2(23054, "****************************** Captured Lines (start) *****************************"); @@ -330,6 +360,49 @@ int64_t Test::CaptureLogs::countTextFormatLogLinesContaining(const std::string& msgs.begin(), msgs.end(), [&](const std::string& s) { return stringContains(s, needle); }); } +namespace { +bool isSubset(BSONObj haystack, BSONObj needle) { + for (const auto& element : needle) { + auto foundElement = haystack[element.fieldNameStringData()]; + if (foundElement.eoo()) { + return false; + } + + // Only validate if an element exists if it is marked as undefined. + if (element.type() == Undefined) { + continue; + } + + if (foundElement.canonicalType() != element.canonicalType()) { + return false; + } + + switch (element.type()) { + case Object: + if (!isSubset(foundElement.Obj(), element.Obj())) { + return false; + } + return true; + case Array: + // not supported + invariant(false); + default: + if (SimpleBSONElementComparator::kInstance.compare(foundElement, element) != 0) { + return false; + } + } + } + + return true; +} +} // namespace + +int64_t Test::CaptureLogs::countBSONFormatLogLinesIsSubset(const BSONObj needle) { + const auto& msgs = getCapturedBSONFormatLogMessages(); + return std::count_if( + msgs.begin(), msgs.end(), [&](const BSONObj s) { return isSubset(s, needle); }); +} + void Test::startCapturingLogMessages() { _captureLogs->startCapturingLogMessages(); } @@ -339,9 +412,15 @@ void Test::stopCapturingLogMessages() { const std::vector<std::string>& Test::getCapturedTextFormatLogMessages() const { return _captureLogs->getCapturedTextFormatLogMessages(); } +const std::vector<BSONObj> Test::getCapturedBSONFormatLogMessages() const { + return _captureLogs->getCapturedBSONFormatLogMessages(); +} int64_t Test::countTextFormatLogLinesContaining(const std::string& needle) { return _captureLogs->countTextFormatLogLinesContaining(needle); } +int64_t Test::countBSONFormatLogLinesIsSubset(const BSONObj needle) { + return _captureLogs->countBSONFormatLogLinesIsSubset(needle); +} void Test::printCapturedTextFormatLogLines() const { _captureLogs->printCapturedTextFormatLogLines(); } diff --git a/src/mongo/unittest/unittest.h b/src/mongo/unittest/unittest.h index 9e2c2fd0518..aef0254c8b3 100644 --- a/src/mongo/unittest/unittest.h +++ b/src/mongo/unittest/unittest.h @@ -585,6 +585,7 @@ protected: * the last call to startCapturingLogMessages() in this test. */ const std::vector<std::string>& getCapturedTextFormatLogMessages() const; + const std::vector<BSONObj> getCapturedBSONFormatLogMessages() const; /** * Returns the number of collected log lines containing "needle". @@ -592,6 +593,21 @@ protected: int64_t countTextFormatLogLinesContaining(const std::string& needle); /** + * Returns the number of collected log lines where "needle" is a subset of a line. + * + * Does a Depth-First-Search of a BSON document. Validates each element in "needle" exists in + * "haystack". It ignores extra elements in "haystack". + * + * In example haystack: { i : 1, a : { b : 1 } }, + * a valid needles include: { i : 1} or {a : { b : 1}} + * It will not find { b: 1 } since it does not search recursively for sub-tree matches. + * + * If a BSON Element is undefined, it simply checks for its existence, not its type or value. + * This allows callers to test for the existence of elements in variable length log lines. + */ + int64_t countBSONFormatLogLinesIsSubset(const BSONObj needle); + + /** * Prints the captured log lines. */ void printCapturedTextFormatLogLines() const; |