mirrors/mongodb
mirrors/mongodb
0
0
Fork 0
mirror of https://github.com/mongodb/mongo.git synced 2024-12-01 09:32:32 +01:00
Code Issues Releases Activity

SERVER-73601 Add info-level logging for DDL oplog entries on primary and secondaries

Browse Source
This commit is contained in:
Kaitlin Mahar 2023-03-04 22:54:20 +00:00 committed by Evergreen Agent
parent 87fa30a0a5
commit 261711676c
7 changed files with 223 additions and 21 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
etc/backports_required_for_multiversion_tests.yml
View File

@ -338,6 +338,8 @@ last-continuous:
ticket: SERVER-69952
- test_file: jstests/core/query/sbe_plan_cache_autoparameterize_ixscan.js
ticket: SERVER-74262
- test_file: jstests/replsets/log_ddl_ops.js
ticket: SERVER-73601
suites: null
last-lts:
all:
@ -745,4 +747,6 @@ last-lts:
ticket: SERVER-74124
- test_file: jstests/core/timeseries/timeseries_filter_extended_range.js
ticket: SERVER-69952
- test_file: jstests/replsets/log_ddl_ops.js
ticket: SERVER-73601
suites: null

85
jstests/replsets/log_ddl_ops.js Normal file
View File

@ -0,0 +1,85 @@
/**
* Tests that we emit info level log messages for DDL write operations at
* the expected points on both primaries and secondaries.
* @tags: [
* uses_transactions,
* ]
*/
(function() {
"use strict";
const name = jsTestName();
const rst = ReplSetTest({name: name, nodes: 2});
rst.startSet();
const nodes = rst.nodeList();
rst.initiate({
"_id": name,
"members": [{"_id": 0, "host": nodes[0]}, {"_id": 1, "host": nodes[1], "priority": 0}]
});
const primary = rst.getPrimary();
const secondary = rst.getSecondary();
const testDB = primary.getDB(name);
const collectionName = "log_collection";
rst.awaitReplication();
assert.commandWorked(testDB.createCollection(collectionName));
assert.commandWorked(testDB.getCollection(collectionName).createIndex({x: 1}));
assert.commandWorked(
testDB.runCommand({collMod: collectionName, index: {keyPattern: {x: 1}, hidden: true}}));
assert.commandWorked(testDB.getCollection(collectionName).dropIndex({x: 1}));
const newCollectionName = "log_collection_renamed";
assert.commandWorked(primary.getDB("admin").runCommand(
{renameCollection: `${name}.${collectionName}`, to: `${name}.${newCollectionName}`}));
assert.commandWorked(testDB.runCommand({drop: newCollectionName}));
assert.commandWorked(testDB.runCommand({dropDatabase: 1}));
const txnCollectionName = "log_collection_txn";
const session = testDB.getMongo().startSession();
const sessionDB = session.getDatabase(name);
session.startTransaction();
assert.commandWorked(sessionDB.createCollection(txnCollectionName));
assert.commandWorked(sessionDB.getCollection(txnCollectionName).createIndex({x: 1}));
session.commitTransaction();
rst.awaitReplication();
const primaryLogCodes = [
7360100, // createIndexes in txn
7360101, // createIndexes
7360102, // create in txn
7360103, // create
7360104, // collMod
7360105, // dropDatabase
7360106, // drop
7360107, // dropIndexes
7360108, // renameCollection
];
for (const code of primaryLogCodes) {
checkLog.contains(primary, code, 1 * 1000);
}
const opsLogged = [
"createIndexes",
"create",
"collMod",
"dropDatabase",
"drop",
"dropIndexes",
"renameCollection",
];
for (const op of opsLogged) {
checkLog.contains(secondary, new RegExp(`7360109.*${op}`), 1 * 1000); // OplogBatcher message
checkLog.contains(secondary, new RegExp(`7360110.*${op}`), 1 * 1000); // OplogApplier message
}
rst.stopSet();
})();

107
src/mongo/db/op_observer/op_observer_impl.cpp
View File

@ -131,11 +131,14 @@ repl::OpTime logOperation(OperationContext* opCtx,
*
* 'fromMigrate' is generally hard-coded to false, but is supplied by a few
* scenarios from mongos related behavior.
*
* If in a transaction, returns a null OpTime. Otherwise, returns the OpTime the operation
* was logged with.
*/
void logMutableOplogEntry(OperationContext* opCtx,
MutableOplogEntry* entry,
OplogWriter* oplogWriter,
bool isRequiredInMultiDocumentTransaction = false) {
repl::OpTime logMutableOplogEntry(OperationContext* opCtx,
MutableOplogEntry* entry,
OplogWriter* oplogWriter,
bool isRequiredInMultiDocumentTransaction = false) {
auto txnParticipant = TransactionParticipant::get(opCtx);
const bool inMultiDocumentTransaction =
txnParticipant && opCtx->writesAreReplicated() && txnParticipant.transactionIsOpen();
@ -146,8 +149,9 @@ void logMutableOplogEntry(OperationContext* opCtx,
if (inMultiDocumentTransaction) {
txnParticipant.addTransactionOperation(opCtx, entry->toReplOperation());
return {};
} else {
logOperation(opCtx, entry, /*assignWallClockTime=*/true, oplogWriter);
return logOperation(opCtx, entry, /*assignWallClockTime=*/true, oplogWriter);
}
}
@ -414,7 +418,24 @@ void OpObserverImpl::onCreateIndex(OperationContext* opCtx,
oplogEntry.setObject(builder.done());
oplogEntry.setFromMigrateIfTrue(fromMigrate);
logMutableOplogEntry(opCtx, &oplogEntry, _oplogWriter.get());
auto opTime = logMutableOplogEntry(opCtx, &oplogEntry, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
if (opTime.isNull()) {
LOGV2(7360100,
"Added oplog entry for createIndexes to transaction",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"object"_attr = oplogEntry.getObject());
} else {
LOGV2(7360101,
"Wrote oplog entry for createIndexes",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
}
}
void OpObserverImpl::onStartIndexBuild(OperationContext* opCtx,
@ -1188,8 +1209,23 @@ void OpObserverImpl::onCreateCollection(OperationContext* opCtx,
if (!createOpTime.isNull()) {
oplogEntry.setOpTime(createOpTime);
}
logMutableOplogEntry(opCtx, &oplogEntry, _oplogWriter.get());
auto opTime = logMutableOplogEntry(opCtx, &oplogEntry, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
if (opTime.isNull()) {
LOGV2(7360102,
"Added oplog entry for create to transaction",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"object"_attr = oplogEntry.getObject());
} else {
LOGV2(7360103,
"Wrote oplog entry for create",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
}
}
void OpObserverImpl::onCollMod(OperationContext* opCtx,
@ -1231,7 +1267,16 @@ void OpObserverImpl::onCollMod(OperationContext* opCtx,
oplogEntry.setUuid(uuid);
oplogEntry.setObject(repl::makeCollModCmdObj(collModCmd, oldCollOptions, indexInfo));
oplogEntry.setObject2(o2Builder.done());
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
auto opTime =
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
LOGV2(7360104,
"Wrote oplog entry for collMod",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
}
// Make sure the UUID values in the Collection metadata, the Collection object, and the UUID
@ -1255,7 +1300,15 @@ void OpObserverImpl::onDropDatabase(OperationContext* opCtx, const DatabaseName&
oplogEntry.setTid(dbName.tenantId());
oplogEntry.setNss({dbName, "$cmd"});
oplogEntry.setObject(BSON("dropDatabase" << 1));
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
auto opTime =
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
LOGV2(7360105,
"Wrote oplog entry for dropDatabase",
"namespace"_attr = oplogEntry.getNss(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
uassert(50714,
"dropping the admin database is not allowed.",
@ -1295,7 +1348,16 @@ repl::OpTime OpObserverImpl::onDropCollection(OperationContext* opCtx,
oplogEntry.setFromMigrateIfTrue(markFromMigrate);
oplogEntry.setObject(BSON("drop" << collectionName.coll()));
oplogEntry.setObject2(makeObject2ForDropOrRename(numRecords));
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
auto opTime =
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
LOGV2(7360106,
"Wrote oplog entry for drop",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
}
uassert(50715,
@ -1349,7 +1411,16 @@ void OpObserverImpl::onDropIndex(OperationContext* opCtx,
oplogEntry.setUuid(uuid);
oplogEntry.setObject(BSON("dropIndexes" << nss.coll() << "index" << indexName));
oplogEntry.setObject2(indexInfo);
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
auto opTime =
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
LOGV2(7360107,
"Wrote oplog entry for dropIndexes",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
}
repl::OpTime OpObserverImpl::preRenameCollection(OperationContext* const opCtx,
@ -1396,8 +1467,16 @@ repl::OpTime OpObserverImpl::preRenameCollection(OperationContext* const opCtx,
oplogEntry.setObject(builder.done());
if (dropTargetUUID)
oplogEntry.setObject2(makeObject2ForDropOrRename(numRecords));
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
auto opTime =
logOperation(opCtx, &oplogEntry, true /*assignWallClockTime*/, _oplogWriter.get());
if (opCtx->writesAreReplicated()) {
LOGV2(7360108,
"Wrote oplog entry for renameCollection",
"namespace"_attr = oplogEntry.getNss(),
"uuid"_attr = oplogEntry.getUuid(),
"opTime"_attr = opTime,
"object"_attr = oplogEntry.getObject());
}
return {};
}

22
src/mongo/db/repl/oplog.cpp
View File

@ -2155,13 +2155,21 @@ Status applyOperation_inlock(OperationContext* opCtx,
Status applyCommand_inlock(OperationContext* opCtx,
const ApplierOperation& op,
OplogApplication::Mode mode) {
LOGV2_DEBUG(21255,
3,
"applying command op: {oplogEntry}, oplog application mode: "
"{oplogApplicationMode}",
"Applying command op",
"oplogEntry"_attr = redact(op->toBSONForLogging()),
"oplogApplicationMode"_attr = OplogApplication::modeToString(mode));
if (op->shouldLogAsDDLOperation()) {
LOGV2(7360110,
"Applying DDL command oplog entry",
"oplogEntry"_attr = op->toBSONForLogging(),
"oplogApplicationMode"_attr = OplogApplication::modeToString(mode));
} else {
LOGV2_DEBUG(21255,
3,
"applying command op: {oplogEntry}, oplog application mode: "
"{oplogApplicationMode}",
"Applying command op",
"oplogEntry"_attr = redact(op->toBSONForLogging()),
"oplogApplicationMode"_attr = OplogApplication::modeToString(mode));
}
// Only commands are processed here.
invariant(op->getOpType() == OpTypeEnum::kCommand);

6
src/mongo/db/repl/oplog_batcher.cpp
View File

@ -171,6 +171,12 @@ StatusWith<std::vector<OplogEntry>> OplogBatcher::getNextApplierBatch(
oplogBatcherPauseAfterSuccessfulPeek.pauseWhileSet();
auto entry = OplogEntry(op);
if (entry.shouldLogAsDDLOperation()) {
LOGV2(7360109,
"Processing DDL command oplog entry in OplogBatcher",
"oplogEntry"_attr = entry.toBSONForLogging());
}
// Check for oplog version change.
if (entry.getVersion() != OplogEntry::kOplogVersion) {
static constexpr char message[] = "Unexpected oplog version";

14
src/mongo/db/repl/oplog_entry.cpp
View File

@ -799,6 +799,20 @@ bool OplogEntry::isSingleOplogEntryTransactionWithCommand() const {
return _entry.isSingleOplogEntryTransactionWithCommand();
}
bool OplogEntry::shouldLogAsDDLOperation() const {
constexpr std::array<std::string_view, 7> ddlOpsToLog{"create",
"drop",
"renameCollection",
"collMod",
"dropDatabase",
"createIndexes",
"dropIndexes"};
return _entry.isCommand() &&
std::find(ddlOpsToLog.begin(),
ddlOpsToLog.end(),
_entry.getObject().firstElementFieldName()) != ddlOpsToLog.end();
}
uint64_t OplogEntry::getApplyOpsIndex() const {
return _applyOpsIndex;
}

6
src/mongo/db/repl/oplog_entry.h
View File

@ -780,6 +780,12 @@ public:
bool isSingleOplogEntryTransaction() const;
bool isSingleOplogEntryTransactionWithCommand() const;
/**
* Returns whether this oplog entry contains a DDL operation. Used to determine whether to
* log the entry.
*/
bool shouldLogAsDDLOperation() const;
/**
* Returns an index of this operation in the "applyOps" entry, if the operation is packed in the
* "applyOps" entry. Otherwise returns 0.