Transaction does not create oplog entry
Juan Reynolds
When I wrap a write op in a transaction it shows up in the collection but not the oplog. When I do not wrap it in a transaction it shows up in the oplog.
I'm using the example code for the nodejs driver at https://docs.mongodb.com/manual/core/transactions/
Is this a limitation on the nodejs driver, a bug or am I doing something wrong?
My environment:
- OS: Ubuntu 18.04
- MongoDb: 4.22
- Nodejs: 10.18.0
- Node mongo driver: 3.4.1
I have a single replica set on a development machine.
Here is rs.status() output:
{
"set" : "rs0",
"date" : ISODate("2020-01-09T11:40:07.263Z"),
"myState" : 1,
"term" : NumberLong(9),
"syncingTo" : "",
"syncSourceHost" : "",
"syncSourceId" : -1,
"heartbeatIntervalMillis" : NumberLong(2000),
"majorityVoteCount" : 1,
"writeMajorityCount" : 1,
"optimes" : {
"lastCommittedOpTime" : {
"ts" : Timestamp(1578570003, 1),
"t" : NumberLong(9)
},
"lastCommittedWallTime" : ISODate("2020-01-09T11:40:03.081Z"),
"readConcernMajorityOpTime" : {
"ts" : Timestamp(1578570003, 1),
"t" : NumberLong(9)
},
"readConcernMajorityWallTime" : ISODate("2020-01-09T11:40:03.081Z"),
"appliedOpTime" : {
"ts" : Timestamp(1578570003, 1),
"t" : NumberLong(9)
},
"durableOpTime" : {
"ts" : Timestamp(1578570003, 1),
"t" : NumberLong(9)
},
"lastAppliedWallTime" : ISODate("2020-01-09T11:40:03.081Z"),
"lastDurableWallTime" : ISODate("2020-01-09T11:40:03.081Z")
},
"lastStableRecoveryTimestamp" : Timestamp(1578569983, 1),
"lastStableCheckpointTimestamp" : Timestamp(1578569983, 1),
"electionCandidateMetrics" : {
"lastElectionReason" : "electionTimeout",
"lastElectionDate" : ISODate("2020-01-09T04:10:41.365Z"),
"electionTerm" : NumberLong(9),
"lastCommittedOpTimeAtElection" : {
"ts" : Timestamp(0, 0),
"t" : NumberLong(-1)
},
"lastSeenOpTimeAtElection" : {
"ts" : Timestamp(1578496799, 1),
"t" : NumberLong(8)
},
"numVotesNeeded" : 1,
"priorityAtElection" : 1,
"electionTimeoutMillis" : NumberLong(10000),
"newTermStartDate" : ISODate("2020-01-09T04:10:42.366Z"),
"wMajorityWriteAvailabilityDate" : ISODate("2020-01-09T04:10:42.404Z")
},
"members" : [
{
"_id" : 0,
"name" : "127.0.0.1:27017",
"ip" : "127.0.0.1",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 26967,
"optime" : {
"ts" : Timestamp(1578570003, 1),
"t" : NumberLong(9)
},
"optimeDate" : ISODate("2020-01-09T11:40:03Z"),
"syncingTo" : "",
"syncSourceHost" : "",
"syncSourceId" : -1,
"infoMessage" : "",
"electionTime" : Timestamp(1578543041, 1),
"electionDate" : ISODate("2020-01-09T04:10:41Z"),
"configVersion" : 1,
"self" : true,
"lastHeartbeatMessage" : ""
}
],
"ok" : 1,
"$clusterTime" : {
"clusterTime" : Timestamp(1578570003, 1),
"signature" : {
"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
"keyId" : NumberLong(0)
}
},
"operationTime" : Timestamp(1578570003, 1)
}
And my code (similar to mongo manual example):
import { MongoClient } from "mongodb";
async function Do() {
const client = new MongoClient('mongodb://localhost:27017?replicaSet=rs0', {useUnifiedTopology: true});
await client.connect();
await client
.db('mydb1')
.collection('foo')
.insertOne({ abc: 0 }, { w: 'majority' }); // this shows up in oplog
const session = client.startSession();
try {
await session.withTransaction(async () => {
const coll1 = client.db('mydb1').collection('foo');
await coll1.insertOne({ abc: 1 }, { session }); // does not show in oplog
await coll1.insertOne({ abc: 2 }, { session });
}, {
readPreference: 'primary',
writeConcern: { w: 'majority' },
readConcern: { level: 'local' },
});
} finally {
await session.endSession();
await client.close();
}
}
Do()
.then(() => console.log('done')) .catch(e => console.log(JSON.stringify(e, null, 2)));
Kevin Adistambha
Hi,
They do show up in the oplog, but maybe not in the format you expected.
I tried running your exact code using MongoDB 4.2.2, then look in the oplog and saw these two lines:
{ "ts" : Timestamp(1578956429, 2), "t" : NumberLong(1), "h" : NumberLong(0), "v" : 2, "op" : "i", "ns" : "mydb1.foo", "ui" : UUID("ba958542-1649-44d9-aba8-72340d524e32"), "wall" : ISODate("2020-01-13T23:00:29.300Z"), "lsid" : { "id" : UUID("ca24e4e3-b966-4508-a662-9518f00b9760"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(1), "stmtId" : 0, "prevOpTime" : { "ts" : Timestamp(0, 0), "t" : NumberLong(-1) }, "o" : { "_id" : ObjectId("5e1cf68d70f05fabbf674445"), "abc" : 0 } }
{ "ts" : Timestamp(1578956429, 3), "t" : NumberLong(1), "h" : NumberLong(0), "v" : 2, "op" : "c", "ns" : "admin.$cmd", "wall" : ISODate("2020-01-13T23:00:29.315Z"), "lsid" : { "id" : UUID("ca24e4e3-b966-4508-a662-9518f00b9760"), "uid" : BinData(0,"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=") }, "txnNumber" : NumberLong(2), "prevOpTime" : { "ts" : Timestamp(0, 0), "t" : NumberLong(-1) }, "o" : { "applyOps" : [ { "op" : "i", "ns" : "mydb1.foo", "ui" : UUID("ba958542-1649-44d9-aba8-72340d524e32"), "o" : { "_id" : ObjectId("5e1cf68d70f05fabbf674446"), "abc" : 1 } }, { "op" : "i", "ns" : "mydb1.foo", "ui" : UUID("ba958542-1649-44d9-aba8-72340d524e32"), "o" : { "_id" : ObjectId("5e1cf68d70f05fabbf674447"), "abc" : 2 } } ] } }
So the first line describes the .insertOne({ abc: 0 }, { w: 'majority' }); operation without transaction, and the second line merged the await coll1.insertOne({ abc: 1 }, { session }); and await coll1.insertOne({ abc: 2 }, { session }); into a single oplog entry under a transaction. It’s under applyOps where it contains the documents.
Note that the oplog format is for internal use only and may change without notice. The above experiment was valid for MongoDB 4.2.2, but it may change in later versions of MongoDB.
If you need to determine changes in a collection/database, then I would suggest using a supported method e.g. change streams instead of looking at the oplog.
Best regards,
Kevin