[SERVER-65553] Atomic applyOps generates a change stream pre-image on secondaries but not on the primary Created: 13/Apr/22  Updated: 27/Oct/23  Resolved: 19/Apr/22

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Josef Ahmad Assignee: Backlog - Query Execution
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-65531 Crash when running applyOps command w... Backlog
is related to SERVER-33326 Remove use of applyOps/doTxn from sha... Closed
is related to SERVER-33182 Remove atomic applyOps Closed
Assigned Teams:
Query Execution
Operating System: ALL
Steps To Reproduce:

db.getSiblingDB('test').createCollection('c', {changeStreamPreAndPostImages: {enabled: true}})
db.getSiblingDB('test').c.insertOne({_id:1, a:"a"})
db.getSiblingDB('test').runCommand({applyOps:[{op:'u', ns:'test.c', o2: {_id:1}, o: {$set:{a:"b"}}}]})

Results:

MongoDB Enterprise replset:PRIMARY> db.getSiblingDB('config').system.preimages.find().itcount()
0

MongoDB Enterprise replset:SECONDARY> db.getSiblingDB('config').system.preimages.find()
{ "_id" : { "nsUUID" : UUID("efa189d2-9da8-40b8-9de2-baa08cae4669"), "ts" : Timestamp(1649864240, 1), "applyOpsIndex" : NumberLong(0) }, "operationTime" : ISODate("2022-04-13T15:37:20.364Z"), "preImage" : { "_id" : 1, "a" : "a" } }

Oplog:

{ "op" : "c", "ns" : "test.$cmd", "o" : { "applyOps" : [ { "op" : "u", "ns" : "test.c", "o2" : { "_id" : 1 }, "o" : { "$set" : { "a" : "b" } }, "ui" : UUID("efa189d2-9da8-40b8-9de2-baa08cae4669") } ], "lsid" : { "id" : UUID("d2de497f-e3a4-4c07-979b-629bda64c9e9") }, "$clusterTime" : { "clusterTime" : Timestamp(1649864239, 2), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$db" : "test" }, "ts" : Timestamp(1649864240, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:37:20.364Z") }
{ "op" : "i", "ns" : "test.c", "ui" : UUID("efa189d2-9da8-40b8-9de2-baa08cae4669"), "o" : { "_id" : 1, "a" : "a" }, "o2" : { "_id" : 1 }, "ts" : Timestamp(1649864239, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:37:19.392Z") }
{ "op" : "c", "ns" : "test.$cmd", "ui" : UUID("efa189d2-9da8-40b8-9de2-baa08cae4669"), "o" : { "create" : "c", "changeStreamPreAndPostImages" : { "enabled" : true }, "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1649864239, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:37:19.356Z") }

Participants:

 Description   

By design, atomic applyOps does not generate a change stream pre-image (kApplyOpsCmd is excluded here). However, the secondaries replicate the applyOps statements without knowing whether they originated from an applyOps command, and they generate a change stream pre-image. This can result in replica set inconsistencies, as the secondaries may hold content in config.system.preimages that is not existent on the primary.



 Comments   
Comment by Josef Ahmad [ 13/Apr/22 ]

Including kApplyOpsCmd to shouldRecordChangeStreamPreImage would not resolve the issue because the change stream pre-image recorded on the primary would have an invalid timestamp (0,0) that is not representative of the update ((1649864643, 3) in this example).

Oplog (note the latest entry indicating we had written a change stream pre-image with timestamp 0,0) :

{ "op" : "c", "ns" : "admin.$cmd", "o" : { "applyOps" : [ { "op" : "d", "ns" : "config.system.preimages", "ui" : UUID("40a7ae9a-5e7c-459f-8c54-1430139e34fe"), "o" : { "_id" : { "nsUUID" : UUID("6010325b-ecc9-48ab-ab82-7dd9d2ea0216"), "ts" : Timestamp(0, 0), "applyOpsIndex" : NumberLong(0) } } } ] }, "ts" : Timestamp(1649864653, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:44:13.176Z") }
{ "op" : "c", "ns" : "test.$cmd", "o" : { "applyOps" : [ { "op" : "u", "ns" : "test.c", "o2" : { "_id" : 1 }, "o" : { "$set" : { "a" : "b" } }, "ui" : UUID("6010325b-ecc9-48ab-ab82-7dd9d2ea0216") } ], "lsid" : { "id" : UUID("56643d1f-5fe4-4eef-a33a-53dee297df98") }, "$clusterTime" : { "clusterTime" : Timestamp(1649864643, 2), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$db" : "test" }, "ts" : Timestamp(1649864643, 3), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:44:03.526Z") }
{ "op" : "i", "ns" : "test.c", "ui" : UUID("6010325b-ecc9-48ab-ab82-7dd9d2ea0216"), "o" : { "_id" : 1, "a" : "a" }, "o2" : { "_id" : 1 }, "ts" : Timestamp(1649864643, 2), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:44:03.510Z") }
{ "op" : "c", "ns" : "test.$cmd", "ui" : UUID("6010325b-ecc9-48ab-ab82-7dd9d2ea0216"), "o" : { "create" : "c", "changeStreamPreAndPostImages" : { "enabled" : true }, "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1649864643, 1), "t" : NumberLong(1), "v" : NumberLong(2), "wall" : ISODate("2022-04-13T15:44:03.474Z") }

Primary:

MongoDB Enterprise replset:PRIMARY> db.getSiblingDB('config').system.preimages.find().itcount()
0

Secondary:

MongoDB Enterprise replset:SECONDARY> db.getSiblingDB('config').system.preimages.find()
{ "_id" : { "nsUUID" : UUID("6010325b-ecc9-48ab-ab82-7dd9d2ea0216"), "ts" : Timestamp(1649864643, 3), "applyOpsIndex" : NumberLong(0) }, "operationTime" : ISODate("2022-04-13T15:44:03.526Z"), "preImage" : { "_id" : 1, "a" : "a" } }

Generated at Thu Feb 08 06:03:00 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.