What does OplogStartMissing during Rollback mean in MongoDB? Why does MongoDB needs to find common point ? What is the intention and necessity.
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] Starting rollback due to OplogStartMissing: Our last optime fetched: { ts: Timestamp(1663318803, 4), t: 95 }. source's GTE: { ts: Timestamp(1663318861, 1), t: 96 }
To give more context here are logs before and after that log event.
2022-09-19T20:30:54.807+0000 I REPL [rsBackgroundSync] Choosing primary as sync source candidate: mongodb-2.mongodb.amazon.svc.cluster.local:27017
2022-09-19T20:30:54.808+0000 I CONNPOOL [RS] Connecting to mongodb-2.mongodb.amazon.svc.cluster.local:27017
2022-09-19T20:30:54.827+0000 I REPL [rsBackgroundSync] Changed sync source from empty to mongodb-2.mongodb.amazon.svc.cluster.local:27017
2022-09-19T20:30:54.919+0000 I NETWORK [conn249] received client metadata from 127.0.0.1:44348 conn249: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.2.11" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] Starting rollback due to OplogStartMissing: Our last optime fetched: { ts: Timestamp(1663318803, 4), t: 95 }. source's GTE: { ts: Timestamp(1663318861, 1), t: 96 }
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] Replication commit point: { ts: Timestamp(0, 0), t: -1 }
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] Rollback using 'recoverToStableTimestamp' method.
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] Scheduling rollback (sync source: mongodb-2.mongodb.amazon.svc.cluster.local:27017)
2022-09-19T20:30:54.921+0000 I ROLLBACK [rsBackgroundSync] transition to ROLLBACK
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] State transition ops metrics: { lastStateTransition: "rollback", userOpsKilled: 0, userOpsRunning: 127 }
2022-09-19T20:30:54.921+0000 I REPL [rsBackgroundSync] transition to ROLLBACK from SECONDARY
2022-09-19T20:30:54.924+0000 I NETWORK [rsBackgroundSync] Skip closing connection for connection # 30
2022-09-19T20:30:54.924+0000 I NETWORK [rsBackgroundSync] Skip closing connection for connection # 15
2022-09-19T20:30:54.924+0000 I ROLLBACK [rsBackgroundSync] Waiting for all background operations to complete before starting rollback
2022-09-19T20:30:54.924+0000 I ROLLBACK [rsBackgroundSync] Finished waiting for background operations to complete before rollback
2022-09-19T20:30:54.924+0000 I ROLLBACK [rsBackgroundSync] finding common point
And then it fails an assertion. I don't know what a stable timestamp is.
2022-09-19T20:31:22.163+0000 I ROLLBACK [rsBackgroundSync] Rollback common point is { ts: Timestamp(1663305863, 2), t: 92 }
2022-09-19T20:31:22.163+0000 F ROLLBACK [rsBackgroundSync] Common point must be at least stable timestamp, common point: Timestamp(1663305863, 2), stable timestamp: Timestamp(1663318691, 1)
2022-09-19T20:31:22.163+0000 F - [rsBackgroundSync] Fatal Assertion 51121 at src/mongo/db/repl/rollback_impl.cpp 969
2022-09-19T20:31:22.163+0000 F - [rsBackgroundSync] \n\n***aborting after fassert() failure\n\n
How is the OplogStartMissing different from stale message as shown below. This is from another scenario.
2022-08-01T02:30:21.915+0000 I REPL [replication-0] We are too stale to use mongodb-0.mongodb.amazon.svc.cluster.local:27017 as a sync source. Blacklisting this sync source because our last fetched timestamp: Timestamp(1659314292, 1) is before their earliest timestamp: Timestamp(1659320029, 301) for 1min until: 2022-08-01T02:31:21.915+0000