[SERVER-44450] Do not add fromMigrate field to applyOps insert oplog entries Created: 05/Nov/19  Updated: 29/Oct/23  Resolved: 27/Mar/20

Status: Closed
Project: Core Server
Component/s: Replication, Write Ops
Affects Version/s: None
Fix Version/s: 4.4.0-rc2, 4.7.0

Type: Bug Priority: Major - P3
Reporter: Charlie Swanson Assignee: Jason Chan
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File apply_ops_upsert.js     File apply_ops_upsert_with_migrate.js     File apply_ops_upsert_with_migrate_and_delete.js    
Issue Links:
Backports
Depends
Issue split
split to SERVER-45033 Log operations we do, not those we we... Closed
Related
related to SERVER-47269 Add uses_change_streams tag to apply_... Closed
related to SERVER-46221 Remove oplogApplicationEnforcesSteady... Open
is related to SERVER-42630 Updates from user-executed "applyOps"... Closed
is related to SERVER-42845 Change streams should return events f... Closed
is related to SERVER-21700 Do not relax constraints during stead... Closed
is related to SERVER-33182 Remove atomic applyOps Closed
Backwards Compatibility: Fully Compatible
Backport Requested:
v4.4
Sprint: Repl 2019-11-18, Repl 2019-12-02, Repl 2020-03-23, Repl 2020-04-06
Participants:

 Description   

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.



 Comments   
Comment by Githook User [ 13/Apr/20 ]

Author:

{'name': 'Jason Chan', 'email': 'jason.chan@10gen.com', 'username': 'jasonjhchan'}

Message: SERVER-44450 Do not add fromMigrate field to applyOps insert oplog entries

(cherry picked from commit 7e12da83457ca5a8e76c7d6f39d6b9bbfad3be92)
Branch: v4.4
https://github.com/mongodb/mongo/commit/c4d62178fc49389241c742a78be1fc0eee279fe7

Comment by Githook User [ 27/Mar/20 ]

Author:

{'email': 'jason.chan@10gen.com', 'name': 'Jason Chan', 'username': 'jasonjhchan'}

Message: SERVER-44450 Do not add fromMigrate field to applyOps insert oplog entries
Branch: master
https://github.com/mongodb/mongo/commit/7e12da83457ca5a8e76c7d6f39d6b9bbfad3be92

Comment by Kevin Rosendahl [ 09/Dec/19 ]

judah.schvimer currently a delete event on a document that doesn't exist is essentially just a no-op (not an issue and not something we have to work around). This is mostly an artifact of Lucene's architecture however (as is the fact that we treat updates as upserts), so in theory if we were to change storage engines down the road for some reason that may or may not be the case any more.

Comment by Judah Schvimer [ 09/Dec/19 ]

I filed SERVER-45033 for the second half of this ticket. I'm renaming this ticket "Do not add fromMigrate field to applyOps insert oplog entries".

Comment by Judah Schvimer [ 09/Dec/19 ]

kevin.rosendahl, how does FTS handle delete events on documents that do not exist?

tess.avitabile, I have confirmed that non-atomic upserts get logged as inserts with no "fromMigrate" field:

[js_test:apply_ops_upsert_with_migrate_and_delete] 2019-12-09T15:48:00.068-0500 [jsTest] {  "op" : "i",  "ns" : "foo.coll",  "ui" : UUID("83f5ed32-deff-4632-b85e-8d87079be08b"),  "o" : {  "_id" : 3,  "x" : 3 },  "ts" : Timestamp(1575924478, 5),  "t" : NumberLong(1),  "wall" : ISODate("2019-12-09T20:47:58.452Z"),  "v" : NumberLong(2) }

I am going to split this ticket in 2. This one for fixing the "fromMigrate" field, that we will target for 4.4, and another to make atomic upserts log as inserts and atomic noop deletes not get logged.

Comment by Kevin Rosendahl [ 06/Dec/19 ]

That summary seems correct from the FTS perspective. Also currently we actually treat updates as upserts anyways (using {{

{fullDocument: "updateLookup"}

}}). 

charlie.swanson to make sure my understanding is correct when you say:

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.

The "showing up twice" refers to if you were to open the change stream on the sharded collection (via a mongos), not on the individual shard (directly to the mongod) as we're doing, correct?

Comment by Judah Schvimer [ 05/Dec/19 ]

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:

  1. '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.
  2. 'atomic' applyOps entries being missing in changeStreams won't cause any problems since mongomirror does not run atomic applyOps.
  3. 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.
Comment by David Golden [ 05/Dec/19 ]

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.

Comment by Charlie Swanson [ 05/Dec/19 ]

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.

Comment by Judah Schvimer [ 05/Dec/19 ]

Sorry about the poor summary. Here's another attempt.

There are a few interrelated weird behaviors.

  1. 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
  2. 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.
    1. No changeStreams return these events.
    2. 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.
    3. 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?

Comment by Kevin Rosendahl [ 05/Dec/19 ]

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

Comment by David Golden [ 04/Dec/19 ]

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?

Comment by Judah Schvimer [ 04/Dec/19 ]

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.

Comment by Judah Schvimer [ 04/Dec/19 ]

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

Comment by Judah Schvimer [ 04/Dec/19 ]

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.

Comment by Judah Schvimer [ 04/Dec/19 ]

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 }

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