Oplog does not record operations within a transaction - MongoDb

Question

If you run the below code, outside a transaction object will appear in the oplog as an insert operation but oplog will have no record of inside a transaction but they will be both saved properly to the collection.

I tried to look up the problem with no luck, although I was able to get a confirmation that in my mongodb server version, oplog will create a separate entry for each operation, although I don't get either the 4.0 style, nor the 4.2!

The Code

    const { MongoClient } = require('mongodb');

    const dbName = "db-name";
    const collectionName = "collection-name";
    const dbUri = "mongodb+srv://<user>:<pass>@<cluster-url>/<db-name>?retryWrites=true&w=majority";
 
    const client = await new MongoClient(dbUri, { useUnifiedTopology: true }).connect();
    const db = client.db(dbName);
    const collection = db.collection(collectionName);

    const session = client.startSession();
    const transactionOptions = {
        readConcern: { level: 'snapshot' },
        writeConcern: { w: 'majority' }
    };

    await collection.insertOne({ name: "outside a transaction" });
    await session.withTransaction(async () => {
        await collection.insertOne({ name: "inside a transaction" }, { session: session});
    }, transactionOptions);

    await session.endSession();
    await client.close();

Oplog Result

Query: db.oplog.rs.find({}).sort({$natural: -1}) Actual Count: 1 Expected Count: 2

{
   "lsid":{
      "id":{
         "$binary":"IwdZfNnGTvGDoABb0gjxXQ==",
         "$type":"4"
      },
      "uid":{
         "$binary":"ddqot68vLpBUPnOuqFj2cdClv/dv/vF9ZVSwknYHEsE=",
         "$type":"0"
      }
   },
   "txnNumber":{
      "$numberLong":"1"
   },
   "op":"i",
   "ns":"testDb.tests",
   "ui":{
      "$binary":"2a1ZJWDySfGuvtgMK2G2gQ==",
      "$type":"4"
   },
   "o":{
      "_id":{
         "$oid":"60f6feb12a662ec3fc985400"
      },
      "name":"outside a transaction"
   },
   "ts":{
      "$timestamp":{
         
      }
   },
   "t":{
      "$numberLong":"73"
   },
   "wall":{
      "$date":"2021-07-20T16:49:53.226Z"
   },
   "v":{
      "$numberLong":"2"
   },
   "stmtId":0,
   "prevOpTime":{
      "ts":{
         "$timestamp":{
            
         }
      },
      "t":{
         "$numberLong":"-1"
      }
   }
}

---

• Mongo Database Version: 4.2
• Mongo Database Setup: 3 Member Replica Set (Hosted on Atlas)
• Mongo Driver: Tried both V3.6 and V4 (both are compatible with the database version)

Answer 1

When I run this test on a MongoDB 5.0 (3-node replicaset) I see the two oplog entries...

use local

db.oplog.rs.find({ns: {$ne: ''}}).sort({ts: -1})

 {
    lsid: {
      id: UUID("74450c89-04ca-441c-93b4-24472c833e98"),
      uid: Binary(Buffer.from("92e7f3b655ee46a4a10212cc1146f3a783e6f4266bef6b5699dbc5528be5177c", "hex"), 0)
    },
    txnNumber: Long("1"),
    op: 'c',
    ns: 'admin.$cmd',
    o: {
      applyOps: [
        {
          op: 'i',
          ns: 'nodetest.mycollection',
          ui: UUID("b6079273-b2de-49a4-b148-837b4ac2c95f"),
          o: {
            _id: ObjectId("60f74ca3601963e6c5ca02f2"),
            name: 'inside a transaction'
          }
        }
      ]
    },
    ts: Timestamp(3, 1626819747),
    t: Long("95"),
    v: Long("2"),
    wall: ISODate("2021-07-20T22:22:27.714Z"),
    prevOpTime: { ts: Timestamp(0, 0), t: Long("-1") }
  },
  {
    lsid: {
      id: UUID("92372b8e-89fd-48ff-ab2a-780520e97c39"),
      uid: Binary(Buffer.from("92e7f3b655ee46a4a10212cc1146f3a783e6f4266bef6b5699dbc5528be5177c", "hex"), 0)
    },
    txnNumber: Long("1"),
    op: 'i',
    ns: 'nodetest.mycollection',
    ui: UUID("b6079273-b2de-49a4-b148-837b4ac2c95f"),
    o: {
      _id: ObjectId("60f74ca3601963e6c5ca02f1"),
      name: 'outside a transaction'
    },
    ts: Timestamp(2, 1626819747),
    t: Long("95"),
    v: Long("2"),
    wall: ISODate("2021-07-20T22:22:27.367Z"),
    stmtId: 0,
    prevOpTime: { ts: Timestamp(0, 0), t: Long("-1") }
  }

Same thing in MongoDB 4.4....

{
    "lsid" : {
        "id" : UUID("8d72b35a-a8d7-4ffd-a56a-1f2f02b944a5"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "op" : "c",
    "ns" : "admin.$cmd",
    "o" : {
        "applyOps" : [
            {
                "op" : "i",
                "ns" : "nodetest.mycollection",
                "ui" : UUID("52fcd28a-9de8-45b0-966a-d1b869976d11"),
                "o" : {
                    "_id" : ObjectId("60f74ead58cd50e7b5ec7e1c"),
                    "name" : "inside a transaction"
                }
            }
        ]
    },
    "ts" : Timestamp(1626820269, 1),
    "t" : NumberLong(185),
    "wall" : ISODate("2021-07-20T22:31:09.111Z"),
    "v" : NumberLong(2),
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    }
}
{
    "lsid" : {
        "id" : UUID("3985c2b0-1863-4718-8851-747ff8160045"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "op" : "i",
    "ns" : "nodetest.mycollection",
    "ui" : UUID("52fcd28a-9de8-45b0-966a-d1b869976d11"),
    "o" : {
        "_id" : ObjectId("60f74eac58cd50e7b5ec7e1b"),
        "name" : "outside a transaction"
    },
    "ts" : Timestamp(1626820268, 2),
    "t" : NumberLong(185),
    "wall" : ISODate("2021-07-20T22:31:08.912Z"),
    "v" : NumberLong(2),
    "stmtId" : 0,
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    }
}

MongoDB 4.2

{
    "ts" : Timestamp(1626820723, 2),
    "t" : NumberLong(501),
    "h" : NumberLong(0),
    "v" : 2,
    "op" : "c",
    "ns" : "admin.$cmd",
    "wall" : ISODate("2021-07-20T22:38:43.304Z"),
    "lsid" : {
        "id" : UUID("0df8170a-6700-4751-9c14-88651ec54f9b"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    },
    "o" : {
        "applyOps" : [
            {
                "op" : "i",
                "ns" : "nodetest.mycollection",
                "ui" : UUID("4c0507b2-8018-48d4-9f80-f2bb6bd227dd"),
                "o" : {
                    "_id" : ObjectId("60f75073abc759e7f6d53ba6"),
                    "name" : "inside a transaction"
                }
            }
        ]
    }
}
{
    "ts" : Timestamp(1626820723, 1),
    "t" : NumberLong(501),
    "h" : NumberLong(0),
    "v" : 2,
    "op" : "i",
    "ns" : "nodetest.mycollection",
    "ui" : UUID("4c0507b2-8018-48d4-9f80-f2bb6bd227dd"),
    "wall" : ISODate("2021-07-20T22:38:43.016Z"),
    "lsid" : {
        "id" : UUID("4983da87-0c9c-448b-8d54-50f3885ce9ce"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "stmtId" : 0,
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    },
    "o" : {
        "_id" : ObjectId("60f75072abc759e7f6d53ba5"),
        "name" : "outside a transaction"
    }
}

MongoDB 4.0

{
    "ts" : Timestamp(1626821049, 3),
    "t" : NumberLong(2),
    "h" : NumberLong("-7247099881451421420"),
    "v" : 2,
    "op" : "c",
    "ns" : "admin.$cmd",
    "wall" : ISODate("2021-07-20T22:44:09.560Z"),
    "lsid" : {
        "id" : UUID("984168e5-c1fd-47cd-9981-acae8585e3e9"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "stmtId" : 0,
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    },
    "o" : {
        "applyOps" : [
            {
                "op" : "i",
                "ns" : "nodetest.mycollection",
                "ui" : UUID("60acd457-0d98-4e06-8921-bf10d1bb63c7"),
                "o" : {
                    "_id" : ObjectId("60f751b926f38ce856f9b08d"),
                    "name" : "inside a transaction"
                }
            }
        ]
    }
}
{
    "ts" : Timestamp(1626821049, 2),
    "t" : NumberLong(2),
    "h" : NumberLong("6159503664626025226"),
    "v" : 2,
    "op" : "i",
    "ns" : "nodetest.mycollection",
    "ui" : UUID("60acd457-0d98-4e06-8921-bf10d1bb63c7"),
    "wall" : ISODate("2021-07-20T22:44:09.266Z"),
    "lsid" : {
        "id" : UUID("8f7d6590-8c7c-4819-9ce7-f69b92725c26"),
        "uid" : BinData(0,"kufztlXuRqShAhLMEUbzp4Pm9CZr72tWmdvFUovlF3w=")
    },
    "txnNumber" : NumberLong(1),
    "stmtId" : 0,
    "prevOpTime" : {
        "ts" : Timestamp(0, 0),
        "t" : NumberLong(-1)
    },
    "o" : {
        "_id" : ObjectId("60f751b926f38ce856f9b08c"),
        "name" : "outside a transaction"
    }
}

Not testing with 3.6 since it is no longer a supported version and never supported transactions anyways.

I had to modify your example program to make it work, here is what I ran for a test...

Modified Test Program

const { MongoClient } = require('mongodb');

const dbName = "nodetest";
const collectionName = "mycollection";
const dbUri = "mongodb://barry:????????@localhost:44011,localhost:44012,localhost:44013/nodetest?replicaSet=replSet&authSource=admin&retryWrites=true&w=majority";

async function run() {
    const client = await new MongoClient(dbUri, { useUnifiedTopology: true }).connect();
    const db = client.db(dbName);
    const collection = db.collection(collectionName);
    
    const session = client.startSession();
    const transactionOptions = {
        readConcern: { level: 'snapshot' },
        writeConcern: { w: 'majority' }
    };
    
    await collection.insertOne({ name: "outside a transaction" });
    await session.withTransaction(async () => {
        await collection.insertOne({ name: "inside a transaction" }, { session: session});
    }, transactionOptions);
    
    await session.endSession();
    await client.close();
}

run().catch(console.dir);