[SERVER-79912] CheckReplDBHash reports failure with system.buckets collections due to invalid BSON Created: 08/Aug/23  Updated: 29/Oct/23  Resolved: 30/Aug/23

Status: Closed
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: 7.2.0-rc0, 7.0.2, 7.1.0-rc1, 6.0.11

Type: Bug Priority: Major - P3
Reporter: Felipe Gasper Assignee: Yuhong Zhang
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Related
is related to SERVER-81044 Handle internal oplog update correctl... Closed
Assigned Teams:
Storage Execution NAMER
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v7.1, v7.0, v6.0
Sprint: Execution NAMR Team 2023-08-21, Execution NAMR Team 2023-09-04
Participants:

 Description   

https://parsley.mongodb.com/resmoke/7cfdaf9a3149e7700db387be776ee626/all?bookmarks=0,577073&shareLine=573444

The key phrase is: "checkReplicatedDataHashes, the two nodes have a different hash for the collection test.system.buckets.timeseries_internal_bounded_sort"

This is the destination cluster in a mongosync run. Notably, mongosync creates time-series collections by creating a system.buckets.mongosync.tmp.$srcUUID collection, then renaming it to the correct system.buckets name, then creating the view separately. That may be part of the cause.



 Comments   
Comment by Githook User [ 01/Sep/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Set `checkExistenceForDiffInsert` to true for oplog entry generated from `$_internalApplyOplogUpdate` update

(cherry picked from commit 806f6d42ee6c2d0a8c1cc7079fb589301961124e)
(cherry picked from commit a572a4c8c9be7865f23d57813959e63a7f6e57c4)
(cherry picked from commit 46ccf953b3045aff73e9657d3286a5488b2fdc4c)
Branch: v6.0
https://github.com/mongodb/mongo/commit/c8effb81643666d0ace1cc82f816a679fbb7af8e

Comment by Githook User [ 01/Sep/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Introduce `checkExistenceForDiffInsert` field to oplog

(cherry picked from commit 923f5a7bf7a2929fad74bc7c798f3c223f106d10)
(cherry picked from commit 0151b5403c96af511594c11a56b702b410a22355)
(cherry picked from commit 9c87b57cd6657a5e090a166f8051ad118fdae52f)
Branch: v6.0
https://github.com/mongodb/mongo/commit/5ec774524eb6f917dbe9fd30e55134f32f145be0

Comment by Githook User [ 01/Sep/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Set `checkExistenceForDiffInsert` to true for oplog entry generated from `$_internalApplyOplogUpdate` update

(cherry picked from commit 806f6d42ee6c2d0a8c1cc7079fb589301961124e)
(cherry picked from commit a572a4c8c9be7865f23d57813959e63a7f6e57c4)
Branch: v7.0
https://github.com/mongodb/mongo/commit/46ccf953b3045aff73e9657d3286a5488b2fdc4c

Comment by Githook User [ 01/Sep/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Introduce `checkExistenceForDiffInsert` field to oplog

(cherry picked from commit 923f5a7bf7a2929fad74bc7c798f3c223f106d10)
(cherry picked from commit 0151b5403c96af511594c11a56b702b410a22355)
Branch: v7.0
https://github.com/mongodb/mongo/commit/9c87b57cd6657a5e090a166f8051ad118fdae52f

Comment by Githook User [ 31/Aug/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Set `checkExistenceForDiffInsert` to true for oplog entry generated from `$_internalApplyOplogUpdate` update

(cherry picked from commit 806f6d42ee6c2d0a8c1cc7079fb589301961124e)
Branch: v7.1
https://github.com/mongodb/mongo/commit/a572a4c8c9be7865f23d57813959e63a7f6e57c4

Comment by Githook User [ 31/Aug/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Introduce `checkExistenceForDiffInsert` field to oplog

(cherry picked from commit 923f5a7bf7a2929fad74bc7c798f3c223f106d10)
Branch: v7.1
https://github.com/mongodb/mongo/commit/0151b5403c96af511594c11a56b702b410a22355

Comment by Githook User [ 29/Aug/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Set `checkExistenceForDiffInsert` to true for oplog entry generated from `$_internalApplyOplogUpdate` update
Branch: master
https://github.com/mongodb/mongo/commit/806f6d42ee6c2d0a8c1cc7079fb589301961124e

Comment by Githook User [ 29/Aug/23 ]

Author:

{'name': 'Yuhong Zhang', 'email': 'yuhong.zhang@mongodb.com', 'username': 'YuhongZhang98'}

Message: SERVER-79912 Introduce `checkExistenceForDiffInsert` field to oplog
Branch: master
https://github.com/mongodb/mongo/commit/923f5a7bf7a2929fad74bc7c798f3c223f106d10

Comment by Felipe Gasper [ 23/Aug/23 ]

yuhong.zhang@mongodb.com It’s hard to test right now due to some temporary breakage. I’ll hopefully confirm later today.

Comment by Yuhong Zhang [ 22/Aug/23 ]

We used to have the assumption that the secondary oplog application of time-series diff update oplog entries could only be generated from user inserts on the view namespace, which is guaranteed to be monotonically increasing, so we performed this optimization to skip checking if a delta insert field already exists.

But this was no longer true after we introduced $_internalApplyOplogUpdate, which can try to diff insert an already existing field. This is only used by mongosync so we just caught this bug now.

I will lower the priority to P3 as it's not affecting other types of collections and not user-facing.

Comment by Yuhong Zhang [ 18/Aug/23 ]

The problematic document has 10 change events:

  1. Insert element index 0-27 at TS{T:1691503442 I:33}
  2. Update (diff insert) element index 28-55 at TS{T:1691503442 I:88}
  3. Update (diff insert) element index 56-83 at {T:1691503442 I:143}
  4. Update (diff insert) element index 84-111 at {T:1691503442 I:198}
  5. Update (diff insert) element index 112-139 at {T:1691503442 I:253}
  6. Update (diff insert) element index 140-167 at {T:1691503442 I:308}
  7. Update (diff insert) element index 168-195 at {T:1691503442 I:363}
  8. Update (diff insert) element index 196-223 at {T:1691503442 I:418}
  9. Update (diff insert) element index 224-251 at {T:1691503442 I:473}
  10. Update (diff insert) element index 252-279 at {T:1691503442 I:528}

The first oplog entry Max mentioned contained the first 6 change events. The second oplog entry should correspond to a refetch, which happened for about 30 seconds (kept getting write conflicts) from the logs. The last occurrence, similar to the previous ones, looks like

[ReplicatorFixture:j4:replicator] 14:04:38.889Z {"level":"debug","serverID":"e84fc7da","mongosyncID":"coordinator","componentName":"Change Event Application","errGroupName":"Change Event Application Group","errGroupRoutineID":"63","componentName":"Change Event Applier 60 (CRUD)","applier":"Change Event Applier 60 (CRUD)","outOfOrder":"true","lastApplyFailed":"true","eventTs":"{T:1691503442 I:33}","tsOfLastApply":"{T:1691503442 I:308}","event":{"_id":{"_data": "8264D24B52000000212B042C0100296E5A1004691307E3B45E4C5993FB97AF6B3D0B7E463C6F7065726174696F6E54797065003C696E736572740046646F63756D656E744B65790046645F6964006464D3C7004C83948224C45DDF000004"},"type":"replace","clusterTime":"{T:1691503442 I:33}","document":"document too long (8334 bytes)","namespace":{"database":"test","collection":"system.buckets.timeseries_internal_bounded_sort"},"collectionUUID":"691307e3-b45e-4c59-93fb-97af6b3d0b7e","documentKey":{"_id": {"$oid":"64d3c7004c83948224c45ddf"}}},"time":"2023-08-08T14:04:38.88804337Z","message":"Refetching document from source."} 

Note it shows tsOfLastApply as {T:1691503442 I:308}, which is where the first oplog entry stopped at. 

After the refetch, we saw several logs like this

[ReplicatorFixture:j4:replicator] 14:04:38.918Z {"level":"debug","serverID":"e84fc7da","mongosyncID":"coordinator","componentName":"Change Event Application","errGroupName":"Change Event Application Group","errGroupRoutineID":"63","componentName":"Change Event Applier 60 (CRUD)","applier":"Change Event Applier 60 (CRUD)","event":{"_id":{"_data": "8264D24B52000001342B042C0100296E5A1004691307E3B45E4C5993FB97AF6B3D0B7E463C6F7065726174696F6E54797065003C7570646174650046646F63756D656E744B65790046645F6964006464D3C7004C83948224C45DDF000004"},"type":"update","clusterTime":"{T:1691503442 I:308}","document":"document too long (0 bytes)","namespace":{"database":"test","collection":"system.buckets.timeseries_internal_bounded_sort"},"collectionUUID":"691307e3-b45e-4c59-93fb-97af6b3d0b7e","documentKey":{"_id": {"$oid":"64d3c7004c83948224c45ddf"}}},"time":"2023-08-08T14:04:38.917909068Z","message":"Skipping event because eventTs ({T:1691503442 I:308}) <= tsOfLastFetch ({T:1691503442 I:308})"} 

They showed that we skipped the first 6 change events since they happened before tsOfLastFetch {T:1691503442 I:308}. This could also explain why we saw the third oplog entry containing the rest of the change events.

So this makes it look like the refetch should fetch the document at TS {T:1691503442 I:308}, which only contains the first 6 change events instead of all 10. Could this be a problem?

Another question for my understanding is, after mongosync receives the change events, what are the exact commands it will run on the destination cluster? I would want to understand better about how the oplog entry gets generated.

Comment by Felipe Gasper [ 15/Aug/23 ]

I’m marking this as a blocker for REP-2771. It may not be directly related to time-series, but mongosync’s (still-in-development) time-series support seems to be what creates it.

Comment by Alexander Komyagin [ 08/Aug/23 ]

Timeseries support is one of the key things on the short-term roadmap (originally planned for the Aug/Sep release). We would definitely appreciate your help here.

Comment by Gregory Noma [ 08/Aug/23 ]

alan.zheng@mongodb.com alex.komyagin@mongodb.com any input on the urgency of this? We could use some clarity on the timeline for mongosync supporting time-series collections

CC irwin.dolobowsky@mongodb.com

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