We have a mongodb 4.2 (stable branch) replica set with three members. It was working for several months without problems. Yesterday one of the secondary members started to do very strange things.
I can see this in the log:
2021-11-14T12:47:33.690+0100 I ELECTION [replexec-5] Scheduling catchup takeover at 2021-11-14T12:48:03.690+0100
2021-11-14T12:47:33.955+0100 I REPL [replexec-5] Canceling catchup takeover callback
2021-11-14T12:47:36.386+0100 I ELECTION [replexec-5] Scheduling catchup takeover at 2021-11-14T12:48:06.386+0100
2021-11-14T12:47:37.971+0100 I REPL [replexec-3] Canceling catchup takeover callback
2021-11-14T12:47:45.137+0100 I ELECTION [replexec-3] Scheduling catchup takeover at 2021-11-14T12:48:15.137+0100
2021-11-14T12:47:45.159+0100 I REPL [repl-writer-worker-133] applied op: CRUD { ts: Timestamp(1636890464, 16), t: 805, h: 0, v: 2, op: "i", ns: "mydb.www.user_view_events", ui: UUID("698007b9-599a-41ad-97b1-6bebef831a08"), wall: new Date(1636890464676), lsid: { id: UUID("9512b937-bc4d-4ebc-84e0-26e21548578b"), uid: BinData(0, 6399AB0DAC62F20BFC466753B10FB58FB7E692BEC952C69B84D997021794D1F8) }, txnNumber: 5182, stmtId: 0, prevOpTime: { ts: Timestamp(0, 0), t: -1 }, o: { _id: ObjectId('6190f761d9c972221fee6e86'), cluster: "kifu", data: { event: "exercise", exercise_event: "evaluate", evaluation_result: { success: false, solution: [ "falanx"], successPercent: 0.0 }, published: true, evaluationTimeStamp: ""Nov 14, 2021, 12:47:45 PM"" }, eventDate: new Date(1636890465013), instance: "tomcat01", } }, took 117ms
2021-11-14T12:47:46.003+0100 I REPL [replexec-3] Canceling catchup takeover callback
2021-11-14T12:47:47.929+0100 I ELECTION [replexec-3] Scheduling catchup takeover at 2021-11-14T12:48:17.929+0100
2021-11-14T12:47:48.010+0100 I REPL [replexec-3] Canceling catchup takeover callback
2021-11-14T12:47:51.025+0100 I ELECTION [replexec-3] Scheduling catchup takeover at 2021-11-14T12:48:21.025+0100
2021-11-14T12:47:52.032+0100 I REPL [replexec-3] Canceling catchup takeover callback
2021-11-14T12:47:53.821+0100 I ELECTION [replexec-3] Scheduling catchup takeover at 2021-11-14T12:48:23.821+0100
2021-11-14T12:47:54.039+0100 I REPL [replexec-5] Canceling catchup takeover callback
2021-11-14T12:47:59.480+0100 I ELECTION [replexec-3] Scheduling catchup takeover at 2021-11-14T12:48:29.480+0100
2021-11-14T12:48:00.062+0100 I REPL [replexec-3] Canceling catchup takeover callback
2021-11-14T12:48:02.377+0100 I ELECTION [replexec-5] Scheduling catchup takeover at 2021-11-14T12:48:32.377+0100
2021-11-14T12:48:04.076+0100 I REPL [replexec-5] Canceling catchup takeover callback
This never stops. I suspect that one schedule/cancel pair happens one for every heartbeat. As you can see, the member also replicates CRUD operations from the primary. All members have the same OS version and the same NTP client setup (sytem clocks are in sync).
"Catchup takeover" usually means that the secondary thinks that it is ahead of the primary. This should rarely happen. I have no explanation. We could delete the whole member and recreate it. But we only have three members in this set, and we don't know what is causing the problem. So deleting the member is too risky (it would leave us with just to replicas for several hours).
Any idea what is causing it, and how to fix it?