[DocDB] Retryable request accepted by leader but rejected by followers

[Huqicheng]

Jira Link: DB-12439

Description

We found this from stress test:

Symptom

Leader has accepted the retryable request but when replicating it to followers, the same request was rejected by followers due to Duplicate request error. It can have two different symptoms:

1. Follower1: Node 2d428f411bdb446a8aefbeb752161cea rejected the request (15.182395) because it's duplicate with a pending operation. In this case, tserver will crash because NotifyReplicationFinished called for multiple times. see [DocDB] SIGSEGV in yb-tserver 'NotifyReplicationFinished'. Multiple ReplicationFinished() callbacks triggered in retryable requests #23501

yb-tserver.ip-172-151-23-232.us-west-2.compute.internal.yugabyte.log.INFO.20240814-070504.1444.gz:W0814 07:14:46.291299  1602 raft_consensus.cc:2100] T 32ce0133ec89495d86058db37c32376d P 2d428f411bdb446a8aefbeb752161cea [term 15 FOLLOWER]: StartReplicaOperationUnlocked failed: Illegal state (yb/consensus/replica_state.cc:733): Cannot register retryable request on follower
yb-tserver.ip-172-151-23-232.us-west-2.compute.internal.yugabyte.log.INFO.20240814-070504.1444.gz:W0814 07:14:46.291330  1602 raft_consensus.cc:2117] T 32ce0133ec89495d86058db37c32376d P 2d428f411bdb446a8aefbeb752161cea [term 15 FOLLOWER]: Could not prepare operation for op: 15.182395. Suppressed 286 other warnings. Status for this op: Illegal state (yb/consensus/replica_state.cc:733): Cannot register retryable request on follower

2. Follower2: Node 1a18c2d42cc646fabaeb29f3dcc8f593 rejected the request (15.182395) because its duplicate with a replicated operation. In this case, raft can't replicate any operations until Duplicate request 2881287 get cleaned.

0814 07:10:58.660213 35479 raft_consensus.cc:2100] T 32ce0133ec89495d86058db37c32376d P 1a18c2d42cc646fabaeb29f3dcc8f593 [term 15 FOLLOWER]: StartReplicaOperationUnlocked failed: Illegal state (yb/c
onsensus/retryable_requests.cc:384): Cannot register retryable request on follower: Duplicate request 2881287 from client ee06f9fb-6db4-43bf-8d56-7fba98052c2a (min running 2881282)
W0814 07:10:58.660241 35479 raft_consensus.cc:2117] T 32ce0133ec89495d86058db37c32376d P 1a18c2d42cc646fabaeb29f3dcc8f593 [term 15 FOLLOWER]: Could not prepare operation for op: 15.182395. Suppressed
 0 other warnings. Status for this op: Illegal state (yb/consensus/retryable_requests.cc:384): Cannot register retryable request on follower: Duplicate request 2881287 from client ee06f9fb-6db4-43bf-
8d56-7fba98052c2a (min running 2881282)

Mitigation

This issue should go away when the duplicate requests get cleaned after reaching the retryable request timeout (600secs for ysql and 60s for ycql).

RCA

In progress

Issue Type

kind/bug

Warning: Please confirm that this issue does not contain any sensitive information

• I confirm this issue does not contain any sensitive information.

[Huqicheng]

Some findings:
Assuming ts1 is the leader, ts2 is the follower.

Leader ts1 should crash at around 07:02:13.
Ts2 cleanup the duplicate request at 07:12:13, the request timeout is 10mins, so the duplicate request should be one of the last few requests accepted by the leader at around 07:02:13.

After ts1 restarted, it was elected as leader again.

yb-tserver.ip-172-151-17-9.us-west-2.compute.internal.yugabyte.log.INFO.20240814-070302.1097:I0814 07:10:53.436951  1254 tablet_bootstrap_if.cc:96] T 32ce0133ec89495d86058db37c32376d P dd3f5ec78e7b4dee9e2532fafda15a24: Bootstrap replayed 34/34 log segments. Read operations: 182392, overwritten operations: 0. Pending: 1 replicates. Last read committed op id: 14.182391, last entry metadata: { entry_time: 98831.366s offset: 21711061 active_segment_sequence_number: 34 }, last read entry op id: 14.182392

yb-tserver.ip-172-151-17-9.us-west-2.compute.internal.yugabyte.log.INFO.20240814-070302.1097:I0814 07:10:56.667130  1539 replica_state.cc:796] T 32ce0133ec89495d86058db37c32376d P dd3f5ec78e7b4dee9e2532fafda15a24 [term 15 LEADER]: Advanced the committed_op_id across terms. Last committed operation was: 14.182391 New committed index is: 15.182393

From the LMP error message, follower ts2 should have replicated 182394.

yb-tserver.ip-172-151-17-9.us-west-2.compute.internal.yugabyte.log.INFO.20240814-070302.1097:I0814 07:10:59.171384  1286 consensus_queue.cc:1309] T 32ce0133ec89495d86058db37c32376d P dd3f5ec78e7b4dee9e2532fafda15a24 [LEADER]: Got LMP mismatch error from peer: { peer: 1a18c2d42cc646fabaeb29f3dcc8f593 is_new: 0 last_received: 15.182394 next_index: 182395 last_known_committed_idx: 182394 is_last_exchange_successful: 0 needs_remote_bootstrap: 0 member_type: VOTER num_sst_files: 3 last_applied: 15.182394 last_successful_communication_time: 0ms ago}

OP 182395 has the duplicate request id 2881287 but was accepted by the leader ts1.

Some possibilities:

1. The old request 2881287 got cleaned at leader side.
   1.1 Time-based GC, should be GCed after 10 mins.
   Impossible, because the OP should be registered at around 07:02:13 but the duplicate request was accepted at around 07:10:59, which is less than 10mins
   1.2 min running id-based GC, a request should be GCed when client reports a min running id greater than its request id.
   Impossible, because the duplicate request should be rejected due to Expired request id.
2. The old request 2881287 was not added to RetryableRequests at leader side.
   Maybe..
3. Client which wrote request 2881287 got evicted so that we can't find the min running id.
   Unlikely, GC algorithm will retain the client for 10 more minutes when it finds the client has 0 requests.