Info

SERVER-42630 describes a case where an update entry will be written to the oplog as part of an applyOps but the actual performed operation may be an insert. This can be misleading or wrong for change streams. Currently change streams ignore user-generated applyOps entries but SERVER-42845 tracks the work to change that. There are some comment threads on that ticket describing why, and judah.schvimer offers a proposed solution in this comment.

Top User Comments

judah.schvimer commented on Thu, 5 Dec 2019 22:17:17 +0000: I think changeStreams resumability won't be a problem based on david.golden's point, but if a user opens up a new changeStream concurrently with a mongomirror import, they could miss insert events. Ok, so it sounds like, for mongomirror and FTS: 'fromMigrate' fields in insert oplog entries would be a problem in general for users who open up changeStreams concurrently with a mongomirror import, though not for FTS. 'atomic' applyOps entries being missing in changeStreams won't cause any problems since mongomirror does not run atomic applyOps. upserts being logged as updates instead of inserts and no-op deletes being logged won't cause any problems since mongomirror does not run atomic applyOps, and these quirks only show up in atomic applyOps. david.golden commented on Thu, 5 Dec 2019 21:39:54 +0000: Given that cluster times will be different between old and new clusters, I don't see how users could migrate change streams without some quiet "no writes" period anyway.  Also, IIRC, I think mongomirror intentionally doesn't do atomic applyOps. charlie.swanson commented on Thu, 5 Dec 2019 19:13:46 +0000: I can't say I've fully digested all this information but I did want to hop in with a hypothesis of why this matters. If mongomirror is using applyOps and is the tool of choice for migrating into atlas, it's likely to have adverse affects on change streams that need to move from one deployment into atlas. Without this quirk, I suspect it would be possible (though likely difficult) to migrate a change stream from one to the other without losing events. As a caveat to this whole thing: I know hardly anything about the process of migrating into atlas or using mongomirror. I would also like to note the risk of using "showMigrationEvents". This 'fromMigrate' flag overlaps with the flag used to mark oplog entries that should be ignored because they are coming from an actual chunk migration and would otherwise show up twice in the change stream. judah.schvimer commented on Thu, 5 Dec 2019 15:06:18 +0000: Sorry about the poor summary. Here's another attempt. There are a few interrelated weird behaviors. When a primary receives an "applyOps" command with an insert entry it writes an oplog entry that includes a "fromMigrate:true" field. Normal changeStreams do not return these events, though it appears when "showMigrationEvents" is specified, then these are returned. I've amended the test here: apply_ops_upsert_with_migrate.js When a primary receives an "applyOps" command that exclusively includes CRUD ops and does not specify "allowAtomic:false", it writes a "c" oplog entry with command type "applyOps" containing the CRUD ops. No changeStreams return these events. If one of these operations is an update, and the server actually did an upsert, the "applyOps" oplog entry the primary writes contains an update "u" op, not an insert "i" op. This operation is not included in any changeStreams per the previous point. If it were, however, then consumers of change streams would see an update operation on a document that did not exist. To be consistent with the cluster, the update must be treated as an insert/upsert. I tested deletes here ( apply_ops_upsert_with_migrate_and_delete.js ). If one of these operations is a delete, and the server actually didn't do any deletes, the "applyOps" oplog entry the primary writes will still contain a delete "d" op. This operation is not included in any changeStreams per the previous point. If it were, however, then consumers of change streams would see a delete operation on a document that did not exist. This operation can be ignored. I'm interested in gauging the priority of fixing these quirks. Do you know how much these quirks will affect mongomirror/FTS? kevin.rosendahl commented on Thu, 5 Dec 2019 07:46:09 +0000: I'm not quite sure I follow what the issue you think downstreams will hit (can't figure out what the fassert is being caused by), but it's probably helpful to know that currently FTS actually does get events for oplog entries with "fromMigrate", so there may not be much of an impact on us if I'm understanding properly. The "showMigrationEvents" option was added for our use case (which is that for sharded clusters we still open change streams on each replica set individually, so we want to get the migration events). david.golden commented on Wed, 4 Dec 2019 23:07:58 +0000: I'm not sure I fully follow what the concern is for mongomirror/mongorestore.  I think you're proposing that the ops sent via applyOps might not resemble the actual ops written to the destination oplog?  (Because of converting updates to inserts?)  And that it might affect ops that have "fromMigrate" on a destination of mirror/restore?  If those are the two changes, I don't think there's much impact for mirror/restore on the first one.  Maybe test breakage.  As for the "fromMigrate" part, I'm not sure.  For Atlas Live Migrate, I don't think it matters if ops written to the destination have fromMigrate or not, as they're not supposed to be using the destination.  For off-label use of mongomirror or general use of mongorestore, I don't know that we promise anything about whether mirror/restoration operations will be visible in change streams. Is there anything I've missed? judah.schvimer commented on Wed, 4 Dec 2019 22:55:17 +0000: I think we both need to fix how the oplog entries are written into the oplog and the fact that change streams ignores them. If we just make change streams return the missing events, I expect downstream consumers would hit similar problems to the above fassert. kevin.rosendahl and david.golden, do you have any thoughts on how much this will affect mongomirror users (since it runs applyOps) and FTS users (since it uses changeStreams)? I also don't think change streams will be able to stop filtering out the "fromMigrate" containing events since that would also display chunk migration events we do not want change streams to return. judah.schvimer commented on Wed, 4 Dec 2019 22:43:41 +0000: One last piece of data: In SERVER-42630, it was unclear to me why it was an initial-sync only problem. It seems like it’s relevant to secondary application in general, when fetching missing documents wouldn’t have masked it. It’s because we always upsert outside of initial sync. If we removed that line as we want to in SERVER-21700 and always passed false to “shouldAlwaysUpsert”, and we also removed this line that adds a "b" field to derived ops then the test would crash. If we logged what we did instead of what we were told to do, then we shouldn’t need to add the “b”, we would log an insert rather than an update in the above case, and we would ignore errors as needed in initial sync appropriately. diff for fassert on 58abcf6577982367232a6c76d1ee277a4031ed3c with apply_ops_upsert.js: diff --git a/src/mongo/db/repl/apply_ops.cpp b/src/mongo/db/repl/apply_ops.cpp index 297934bbbc..197d229d64 100644 --- a/src/mongo/db/repl/apply_ops.cpp +++ b/src/mongo/db/repl/apply_ops.cpp @@ -526,7 +526,7 @@ void ApplyOps::extractOperationsTo(const OplogEntry& applyOpsOplogEntry, // Oplog entries can have an oddly-named "b" field for "upsert". MongoDB stopped creating // such entries in 4.0, but we can use the "b" field for the extracted entry here. if (alwaysUpsert && !operationDoc.hasField("b")) { - builder.append("b", true); + //builder.append("b", true); } builder.appendElementsUnique(topLevelDoc); diff --git a/src/mongo/db/repl/oplog_applier_impl.cpp b/src/mongo/db/repl/oplog_applier_impl.cpp index b036bad722..e46879c1d4 100644 --- a/src/mongo/db/repl/oplog_applier_impl.cpp +++ b/src/mongo/db/repl/oplog_applier_impl.cpp @@ -921,7 +921,7 @@ Status applyOplogEntryOrGroupedInserts(OperationContext* opCtx, Status status = applyOperation_inlock(opCtx, db, entryOrGroupedInserts, - shouldAlwaysUpsert, + false, oplogApplicationMode, incrementOpsAppliedStats); if (!status.isOK() && status.code() == ErrorCodes::WriteConflict) { judah.schvimer commented on Wed, 4 Dec 2019 22:40:13 +0000: We don't see change events for documents with _id's 1,5,6,7. Commands: assert.commandWorked(pDB.runCommand( {applyOps: [{op: "u", ns: nss(dbName, collName), o2: {_id: count}, o: {$set: {x: count++}}}]})); assert.commandWorked( pDB.runCommand({applyOps: [{op: "i", ns: nss(dbName, collName), o: {_id: count++}}]})); assert.commandWorked(pDB.runCommand( {applyOps: [{op: "i", ns: nss(dbName, collName), o: {_id: count++}}], allowAtomic: false})); assert.commandWorked(pDB.runCommand({ applyOps: [ {op: "i", ns: nss(dbName, collName), o: {_id: count}}, {op: "c", ns: nss(dbName, "$cmd"), o: {create: "other" + count++}} ] })); The atomic update doesn't have an event, and none of the appleOps commands with an insert get an event due to the mysteriously added "fromMigrate" field. When fixing this we'll want to also test "delete" operations. The base commit for these tests was 58abcf6577982367232a6c76d1ee277a4031ed3c. judah.schvimer commented on Wed, 4 Dec 2019 22:35:36 +0000: The behavior can clearly be seen in this test: apply_ops_upsert.js. Ops: pDB.createCollection(collName); let count = 0; assert.commandWorked(pDB[collName].update({_id: count}, {x: count++}, {upsert: true})); assert.commandWorked(pDB.runCommand( {applyOps: [{op: "u", ns: nss(dbName, collName), o2: {_id: count}, o: {$set: {x: count++}}}]})); assert.commandWorked(pDB.runCommand({ applyOps: [{op: "u", ns: nss(dbName, collName), o2: {_id: count}, o: {$set: {x: count++}}}], allowAtomic: false })); assert.commandWorked(pDB.runCommand({ applyOps: [ {op: "u", ns: nss(dbName, collName), o2: {_id: count}, o: {$set: {x: count}}}, {op: "c", ns: nss(dbName, "$cmd"), o: {create: "other" + count++}} ] })); assert.commandWorked(pDB[collName].insert({_id: count++})); assert.commandWorked( pDB.runCommand({applyOps: [{op: "i", ns: nss(dbName, collName), o: {_id: count++}}]})); assert.commandWorked(pDB.runCommand( {applyOps: [{op: "i", ns: nss(dbName, collName), o: {_id: count++}}], allowAtomic: false})); assert.commandWorked(pDB.runCommand({ applyOps: [ {op: "i", ns: nss(dbName, collName), o: {_id: count}}, {op: "c", ns: nss(dbName, "$cmd"), o: {create: "other" + count++}} ] })); assert.commandWorked(pDB["end"].insert({_id: 0})); You can see the oplog entries here: [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] ---- [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] Dumping the latest 100 documents that match { } from the oplog oplog.rs of jedbartlet:20020 [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] { "op" : "i", "ns" : "foo.end", "ui" : UUID("e981704b-bf89-447e-87d8-3a75d2afe760"), "o" : { "_id" : 0 }, "ts" : Timestamp(1575498632, 7), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.332Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "ui" : UUID("e981704b-bf89-447e-87d8-3a75d2afe760"), "o" : { "create" : "end", "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1575498632, 6), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.331Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "ui" : UUID("1cdd1846-12c4-4660-a778-74544a5afe0a"), "o" : { "create" : "other7" }, "ts" : Timestamp(1575498632, 5), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.173Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 7 }, "ts" : Timestamp(1575498632, 4), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.096Z"), "v" : NumberLong(2), "fromMigrate" : true } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.758-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 6 }, "ts" : Timestamp(1575498632, 3), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.076Z"), "v" : NumberLong(2), "fromMigrate" : true } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "o" : { "applyOps" : [ { "op" : "i", "ns" : "foo.coll", "o" : { "_id" : 5 }, "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba") } ], "lsid" : { "id" : UUID("880314e7-a1d4-4204-b875-72e2d260935c") }, "$clusterTime" : { "clusterTime" : Timestamp(1575498632, 1), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$readPreference" : { "mode" : "secondaryPreferred" }, "$db" : "foo" }, "ts" : Timestamp(1575498632, 2), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.056Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 4 }, "ts" : Timestamp(1575498632, 1), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.032Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "ui" : UUID("a3e299a0-6cd0-422a-b680-9ef522625e2a"), "o" : { "create" : "other3" }, "ts" : Timestamp(1575498631, 6), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:32.004Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 3, "x" : 3 }, "ts" : Timestamp(1575498631, 5), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:31.925Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 2, "x" : 2 }, "ts" : Timestamp(1575498631, 4), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:31.904Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "o" : { "applyOps" : [ { "op" : "u", "ns" : "foo.coll", "o2" : { "_id" : 1 }, "o" : { "$set" : { "x" : 1 } }, "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba") } ], "lsid" : { "id" : UUID("880314e7-a1d4-4204-b875-72e2d260935c") }, "$clusterTime" : { "clusterTime" : Timestamp(1575498631, 2), "signature" : { "hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="), "keyId" : NumberLong(0) } }, "$readPreference" : { "mode" : "secondaryPreferred" }, "$db" : "foo" }, "ts" : Timestamp(1575498631, 3), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:31.882Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "i", "ns" : "foo.coll", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "_id" : 0, "x" : 0 }, "ts" : Timestamp(1575498631, 2), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:31.845Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "c", "ns" : "foo.$cmd", "ui" : UUID("875e448b-688d-448e-abe2-d426633ce1ba"), "o" : { "create" : "coll", "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1575498631, 1), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:31.802Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "n", "ns" : "", "o" : { "awaitLastStableRecoveryTimestamp" : 1 }, "ts" : Timestamp(1575498628, 1), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:28.791Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.759-0500 [jsTest] { "op" : "n", "ns" : "", "o" : { "msg" : "Reconfig set", "version" : 2 }, "ts" : Timestamp(1575498627, 5), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:27.092Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "i", "ns" : "admin.system.keys", "ui" : UUID("99e2e03a-accc-49c0-9114-fd624554896b"), "o" : { "_id" : NumberLong("6766715077857902594"), "purpose" : "HMAC", "key" : BinData(0,"JKUgiC/83p8rvi5y6g1Mo7Rcb5Q="), "expiresAt" : Timestamp(1591050627, 0) }, "ts" : Timestamp(1575498627, 4), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:27.084Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "i", "ns" : "admin.system.keys", "ui" : UUID("99e2e03a-accc-49c0-9114-fd624554896b"), "o" : { "_id" : NumberLong("6766715077857902593"), "purpose" : "HMAC", "key" : BinData(0,"4YC20NAVAGOGyhvLrUuJMMZYYbI="), "expiresAt" : Timestamp(1583274627, 0) }, "ts" : Timestamp(1575498627, 3), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:27.068Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "c", "ns" : "admin.$cmd", "ui" : UUID("99e2e03a-accc-49c0-9114-fd624554896b"), "o" : { "create" : "system.keys", "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1575498627, 2), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:27.066Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "n", "ns" : "", "o" : { "msg" : "new primary" }, "ts" : Timestamp(1575498627, 1), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:27Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "c", "ns" : "config.$cmd", "ui" : UUID("25623e24-8b6d-4720-8e4f-821fa124f459"), "o" : { "create" : "transactions", "idIndex" : { "v" : 2, "key" : { "_id" : 1 }, "name" : "_id_" } }, "ts" : Timestamp(1575498626, 3), "t" : NumberLong(1), "wall" : ISODate("2019-12-04T22:30:26.998Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] { "op" : "n", "ns" : "", "o" : { "msg" : "initiating set" }, "ts" : Timestamp(1575498626, 1), "wall" : ISODate("2019-12-04T22:30:26.750Z"), "v" : NumberLong(2) } [js_test:apply_ops_upsert] 2019-12-04T17:30:32.760-0500 [jsTest] ---- And the change stream events here: [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 "_id" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 "_data" : "825DE83387000000022B022C0100296E5A1004875E448B688D448EABE2D426633CE1BA461E5F696400290004", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 "_typeBits" : BinData(0,"QA==") [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.047-0500 "operationType" : "insert", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "clusterTime" : Timestamp(1575498631, 2), [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "fullDocument" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "_id" : 0, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "x" : 0 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "ns" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "db" : "foo", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "coll" : "coll" [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "documentKey" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 "_id" : 0 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.048-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "_id" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "_data" : "825DE83387000000042B022C0100296E5A1004875E448B688D448EABE2D426633CE1BA461E5F6964002B040004", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "_typeBits" : BinData(0,"QA==") [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "operationType" : "insert", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "clusterTime" : Timestamp(1575498631, 4), [js_test:apply_ops_upsert] 2019-12-04T17:30:33.094-0500 "fullDocument" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "_id" : 2, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "x" : 2 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "ns" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "db" : "foo", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "coll" : "coll" [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "documentKey" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 "_id" : 2 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.095-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 "_id" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 "_data" : "825DE83387000000052B022C0100296E5A1004875E448B688D448EABE2D426633CE1BA461E5F6964002B060004", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 "_typeBits" : BinData(0,"QA==") [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 "operationType" : "insert", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.128-0500 "clusterTime" : Timestamp(1575498631, 5), [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "fullDocument" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "_id" : 3, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "x" : 3 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "ns" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "db" : "foo", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "coll" : "coll" [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.129-0500 "documentKey" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.130-0500 "_id" : 3 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.130-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.130-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.161-0500 { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.161-0500 "_id" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.161-0500 "_data" : "825DE83388000000012B022C0100296E5A1004875E448B688D448EABE2D426633CE1BA461E5F6964002B080004", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.161-0500 "_typeBits" : BinData(0,"QA==") [js_test:apply_ops_upsert] 2019-12-04T17:30:33.161-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "operationType" : "insert", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "clusterTime" : Timestamp(1575498632, 1), [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "fullDocument" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "_id" : 4 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "ns" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "db" : "foo", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.162-0500 "coll" : "coll" [js_test:apply_ops_upsert] 2019-12-04T17:30:33.163-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.163-0500 "documentKey" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.163-0500 "_id" : 4 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.163-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.163-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 "_id" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 "_data" : "825DE83388000000072B022C0100296E5A1004E981704BBF89447E87D83A75D2AFE760461E5F696400290004", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 "_typeBits" : BinData(0,"QA==") [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.195-0500 "operationType" : "insert", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 "clusterTime" : Timestamp(1575498632, 7), [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 "fullDocument" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 "_id" : 0 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 "ns" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.196-0500 "db" : "foo", [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 "coll" : "end" [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 }, [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 "documentKey" : { [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 "_id" : 0 [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 } [js_test:apply_ops_upsert] 2019-12-04T17:30:33.197-0500 }

Steps to Reproduce