summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorHenrik Edin <henrik.edin@mongodb.com>2020-02-18 09:30:37 -0500
committerEvergreen Agent <no-reply@evergreen.mongodb.com>2020-02-18 21:22:37 +0000
commit2b61edc505e45acc7927aee40e4e8abeb99420cd (patch)
tree3de213a9ac3db322e919143f902b2e91c455735b
parent80512e580834b70c97f1facf3cd78da97be643c1 (diff)
downloadmongo-2b61edc505e45acc7927aee40e4e8abeb99420cd.tar.gz
SERVER-46219 Unittests always uses text even if the server uses JSON.
Temporary until we work on fixing the tests. Transaction slow query log logs with both new and old log statement
-rw-r--r--src/mongo/db/curop.cpp13
-rw-r--r--src/mongo/db/repl/oplog_applier_impl.cpp7
-rw-r--r--src/mongo/db/s/transaction_coordinator.cpp7
-rw-r--r--src/mongo/db/transaction_participant.cpp6
-rw-r--r--src/mongo/s/transaction_router.cpp123
-rw-r--r--src/mongo/unittest/unittest_main.cpp14
6 files changed, 91 insertions, 79 deletions
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 385b53141d1..7a4dcec9f1e 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -490,13 +490,12 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx,
_debug.prepareConflictDurationMillis =
duration_cast<Milliseconds>(prepareConflictDurationMicros);
- if (logV2IsJson(serverGlobalParams.logFormat)) {
- logv2::DynamicAttributes attr;
- _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr), &attr);
- LOGV2(51803, "slow query", attr);
- } else {
- log(component) << _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr));
- }
+ 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(component) << _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr));
}
// Return 'true' if this operation should also be added to the profiler.
diff --git a/src/mongo/db/repl/oplog_applier_impl.cpp b/src/mongo/db/repl/oplog_applier_impl.cpp
index 6d9586b8f0c..769f5350921 100644
--- a/src/mongo/db/repl/oplog_applier_impl.cpp
+++ b/src/mongo/db/repl/oplog_applier_impl.cpp
@@ -113,7 +113,7 @@ Status finishAndLogApply(OperationContext* opCtx,
Milliseconds(opDuration),
Milliseconds(serverGlobalParams.slowMS))
.first) {
- if (logV2IsJson(serverGlobalParams.logFormat)) {
+ {
logv2::DynamicAttributes attrs;
@@ -127,7 +127,10 @@ Status finishAndLogApply(OperationContext* opCtx,
attrs.add("duration", opDuration);
LOGV2(51801, "applied op", attrs);
- } else {
+ }
+
+ // TODO SERVER-46219: Log also with old log system to not break unit tests
+ {
StringBuilder s;
s << "applied op: ";
diff --git a/src/mongo/db/s/transaction_coordinator.cpp b/src/mongo/db/s/transaction_coordinator.cpp
index c6ceaede4e5..ce7b9c1e60c 100644
--- a/src/mongo/db/s/transaction_coordinator.cpp
+++ b/src/mongo/db/s/transaction_coordinator.cpp
@@ -422,7 +422,7 @@ void TransactionCoordinator::_done(Status status) {
void TransactionCoordinator::_logSlowTwoPhaseCommit(
const txn::CoordinatorCommitDecision& decision) {
- if (logV2IsJson(serverGlobalParams.logFormat)) {
+ {
logv2::DynamicAttributes attrs;
BSONObjBuilder parametersBuilder;
@@ -492,8 +492,9 @@ void TransactionCoordinator::_logSlowTwoPhaseCommit(
singleTransactionCoordinatorStats.getTwoPhaseCommitDuration(tickSource, curTick)));
LOGV2(51804, "two-phase commit", attrs);
-
- } else {
+ }
+ // TODO SERVER-46219: Log also with old log system to not break unit tests
+ {
LOGV2(22448,
"{twoPhaseCommitInfoForLog_decision}",
"twoPhaseCommitInfoForLog_decision"_attr = _twoPhaseCommitInfoForLog(decision));
diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp
index adf348e6eed..bf072c53f62 100644
--- a/src/mongo/db/transaction_participant.cpp
+++ b/src/mongo/db/transaction_participant.cpp
@@ -2003,11 +2003,13 @@ void TransactionParticipant::Participant::_logSlowTransaction(
opDuration,
Milliseconds(serverGlobalParams.slowMS))
.first) {
- if (logV2IsJson(serverGlobalParams.logFormat)) {
+ {
logv2::DynamicAttributes attr;
_transactionInfoForLog(opCtx, lockStats, terminationCause, readConcernArgs, &attr);
LOGV2_OPTIONS(51802, {logv2::LogComponent::kTransaction}, "transaction", attr);
- } else {
+ }
+ // TODO SERVER-46219: Log also with old log system to not break unit tests
+ {
LOGV2_OPTIONS(
22523,
{logComponentV1toV2(logger::LogComponent::kTransaction)},
diff --git a/src/mongo/s/transaction_router.cpp b/src/mongo/s/transaction_router.cpp
index 21d8d513009..441e7727dbd 100644
--- a/src/mongo/s/transaction_router.cpp
+++ b/src/mongo/s/transaction_router.cpp
@@ -1333,90 +1333,85 @@ BSONObj TransactionRouter::Router::_commitWithRecoveryToken(OperationContext* op
void TransactionRouter::Router::_logSlowTransaction(OperationContext* opCtx,
TerminationCause terminationCause) const {
- if (logV2IsJson(serverGlobalParams.logFormat)) {
- logv2::DynamicAttributes attrs;
- BSONObjBuilder parametersBuilder;
+ logv2::DynamicAttributes attrs;
+ BSONObjBuilder parametersBuilder;
- BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid"));
- _sessionId().serialize(&lsidBuilder);
- lsidBuilder.doneFast();
+ BSONObjBuilder lsidBuilder(parametersBuilder.subobjStart("lsid"));
+ _sessionId().serialize(&lsidBuilder);
+ lsidBuilder.doneFast();
- parametersBuilder.append("txnNumber", o().txnNumber);
- parametersBuilder.append("autocommit", false);
+ parametersBuilder.append("txnNumber", o().txnNumber);
+ parametersBuilder.append("autocommit", false);
- if (!o().readConcernArgs.isEmpty()) {
- o().readConcernArgs.appendInfo(&parametersBuilder);
- }
+ if (!o().readConcernArgs.isEmpty()) {
+ o().readConcernArgs.appendInfo(&parametersBuilder);
+ }
- attrs.add("parameters", parametersBuilder.obj());
+ attrs.add("parameters", parametersBuilder.obj());
- std::string globalReadTimestampTemp;
- if (_atClusterTimeHasBeenSet()) {
- globalReadTimestampTemp = o().atClusterTime->getTime().toString();
- attrs.add("globalReadTimestamp", globalReadTimestampTemp);
- }
+ std::string globalReadTimestampTemp;
+ if (_atClusterTimeHasBeenSet()) {
+ globalReadTimestampTemp = o().atClusterTime->getTime().toString();
+ attrs.add("globalReadTimestamp", globalReadTimestampTemp);
+ }
- if (o().commitType != CommitType::kRecoverWithToken) {
- // We don't know the participants if we're recovering the commit.
- attrs.add("numParticipants", o().participants.size());
- }
+ if (o().commitType != CommitType::kRecoverWithToken) {
+ // We don't know the participants if we're recovering the commit.
+ attrs.add("numParticipants", o().participants.size());
+ }
- if (o().commitType == CommitType::kTwoPhaseCommit) {
- dassert(o().coordinatorId);
- attrs.add("coordinator", *o().coordinatorId);
- }
+ if (o().commitType == CommitType::kTwoPhaseCommit) {
+ dassert(o().coordinatorId);
+ attrs.add("coordinator", *o().coordinatorId);
+ }
- auto tickSource = opCtx->getServiceContext()->getTickSource();
- auto curTicks = tickSource->getTicks();
+ auto tickSource = opCtx->getServiceContext()->getTickSource();
+ auto curTicks = tickSource->getTicks();
- if (terminationCause == TerminationCause::kCommitted) {
- attrs.add("terminationCause", "committed");
+ if (terminationCause == TerminationCause::kCommitted) {
+ attrs.add("terminationCause", "committed");
- dassert(o().metricsTracker->commitHasStarted());
- dassert(o().commitType != CommitType::kNotInitiated);
- dassert(o().abortCause.empty());
- } else {
- attrs.add("terminationCause", "aborted");
+ dassert(o().metricsTracker->commitHasStarted());
+ dassert(o().commitType != CommitType::kNotInitiated);
+ dassert(o().abortCause.empty());
+ } else {
+ attrs.add("terminationCause", "aborted");
- dassert(!o().abortCause.empty());
- attrs.add("abortCause", o().abortCause);
- }
+ dassert(!o().abortCause.empty());
+ attrs.add("abortCause", o().abortCause);
+ }
- const auto& timingStats = o().metricsTracker->getTimingStats();
+ const auto& timingStats = o().metricsTracker->getTimingStats();
- std::string commitTypeTemp;
- if (o().metricsTracker->commitHasStarted()) {
- dassert(o().commitType != CommitType::kNotInitiated);
- commitTypeTemp = commitTypeToString(o().commitType);
- attrs.add("commitType", commitTypeTemp);
+ std::string commitTypeTemp;
+ if (o().metricsTracker->commitHasStarted()) {
+ dassert(o().commitType != CommitType::kNotInitiated);
+ commitTypeTemp = commitTypeToString(o().commitType);
+ attrs.add("commitType", commitTypeTemp);
- attrs.add(
- "commitDuration",
- durationCount<Microseconds>(timingStats.getCommitDuration(tickSource, curTicks)));
- }
+ attrs.add("commitDuration",
+ durationCount<Microseconds>(timingStats.getCommitDuration(tickSource, curTicks)));
+ }
- attrs.add(
- "timeActive",
- durationCount<Microseconds>(timingStats.getTimeActiveMicros(tickSource, curTicks)));
+ attrs.add("timeActive",
+ durationCount<Microseconds>(timingStats.getTimeActiveMicros(tickSource, curTicks)));
- attrs.add(
- "timeInactive",
- durationCount<Microseconds>(timingStats.getTimeInactiveMicros(tickSource, curTicks)));
+ attrs.add("timeInactive",
+ durationCount<Microseconds>(timingStats.getTimeInactiveMicros(tickSource, curTicks)));
- // Total duration of the transaction. Logged at the end of the line for consistency with
- // slow command logging.
- attrs.add("duration",
- duration_cast<Milliseconds>(timingStats.getDuration(tickSource, curTicks)));
+ // Total duration of the transaction. Logged at the end of the line for consistency with
+ // slow command logging.
+ attrs.add("duration",
+ duration_cast<Milliseconds>(timingStats.getDuration(tickSource, curTicks)));
- LOGV2(51805, "transaction", attrs);
+ LOGV2(51805, "transaction", attrs);
- } else {
- LOGV2(22899,
- "transaction {transactionInfoForLog_opCtx_terminationCause}",
- "transactionInfoForLog_opCtx_terminationCause"_attr =
- _transactionInfoForLog(opCtx, terminationCause));
- }
+ // 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/unittest/unittest_main.cpp b/src/mongo/unittest/unittest_main.cpp
index 5f50f71f050..71503cf9c2d 100644
--- a/src/mongo/unittest/unittest_main.cpp
+++ b/src/mongo/unittest/unittest_main.cpp
@@ -34,6 +34,8 @@
#include "mongo/base/initializer.h"
#include "mongo/base/status.h"
#include "mongo/logger/logger.h"
+#include "mongo/logv2/log_domain_global.h"
+#include "mongo/logv2/log_manager.h"
#include "mongo/unittest/unittest.h"
#include "mongo/unittest/unittest_options_gen.h"
#include "mongo/util/log_global_settings.h"
@@ -52,9 +54,19 @@ int main(int argc, char** argv, char** envp) {
::mongo::runGlobalInitializersOrDie(argc, argv, envp);
+ auto& logManager = ::mongo::logv2::LogManager::global();
+ ::mongo::logv2::LogDomainGlobal::ConfigurationOptions logConfig;
+ logConfig.format = ::mongo::logv2::LogFormat::kText;
+
+ Status status = logManager.getGlobalDomainInternal().configure(logConfig);
+ if (!status.isOK()) {
+ std::cerr << status;
+ return EXIT_FAILURE;
+ }
+
moe::OptionSection options;
- Status status = mongo::unittest::addUnitTestOptions(&options);
+ status = mongo::unittest::addUnitTestOptions(&options);
if (!status.isOK()) {
std::cerr << status;
return EXIT_FAILURE;