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)

as I understood you're saying that this code `await collection.insertOne({ name: "outside a transaction" });` is not handled as under transaction. I'm not familiar with `node`, but I believe the node behavior is the same as in other drivers. So the behavior you're seeing is expected since the operation is considered under transaction only if you're passing the related session object into this operation — dododo, Jul 20 '21 at 17:57
@dododo correct, `await collection.insertOne({ name: "outside a transaction" });` is expected to be executed outside of the transaction/session, the problem or my question is, why the oplog captures `outside a transaction` but not `inside a transaction`. — Mazen Elkashef, Jul 20 '21 at 18:03
because it's not inside transaction until you pass a session into `insertOne` — dododo, Jul 20 '21 at 20:47
Lines 4-6 from the bottom, do have an insertOne with a session passed, `await collection.insertOne({ name: "inside a transaction" }, { session: session});` based on the above code there should be 2 entries in the `oplog` but I only get one entry (the one that is not linked to a session). Also I think you're misunderstanding my question or maybe my question is not clear enough, but the question is not about transactions or how they work at all, the question is why the second `insertOne` that lives within a transaction is not appearing in the `oplog` — Mazen Elkashef, Jul 20 '21 at 21:20
when I try to run the code via command `node test.js` I get an error `SyntaxError: await is only valid in async function` — barrypicker, Jul 20 '21 at 22:02
@barrypicker I've simplified the script a little bit for readability, next time I will try to post a runnable version. — Mazen Elkashef, Jul 21 '21 at 14:45

barrypicker · Accepted Answer · 2021-07-20T22:42:46.553

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);

that's great! thanks for taking the time to run those tests, I finally spoke with the mongodb atlas support and they indicated that there are limitations to the instance type I was testing on and once we upgraded the oplog worked as expected, also I think I misunderstood the documentation as I thought starting mongo 4.2 the transaction operations would be represented by it's own document/entry, which is not the case - https://docs.atlas.mongodb.com/reference/unsupported-commands/#limited-commands (M0, M2 and M5 do not support applyOps) — Mazen Elkashef, Jul 21 '21 at 14:54
I will accept this as an answer, If you'd like to update your answer to capture the specific use case with Mongo Atlas, I think it would make the answer more conclusive for future readers, also I think a more accurate query would be `db.oplog.rs.find({ns: "admin.$cmd", op: "c"}).sort({ts: -1})` — Mazen Elkashef, Jul 21 '21 at 14:56

Oplog does not record operations within a transaction - MongoDb

The Code

Oplog Result

1 Answers1