Repository: tikv/tikv (language: rust)

Issue:
TiKV panic with "unstable.slice[1026, 1093] out of bound[1026, 1026]" at src/log_unstable.rs:201
## Bug Report

```
/opt/tidb/kv.log:[2025/01/15 23:14:46.296 +00:00] [FATAL] [lib.rs:480] ["unstable.slice[1026, 1093] out of bound[1026, 1026], raft_id: 29, region_id: 26"] [backtrace="   0: tikv_util::set_panic_hook::{{closure}}
             at /home/stn/tikv/components/tikv_util/src/lib.rs:479:18
   1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2029:9
      std::panicking::rust_panic_with_hook
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:783:13
   2: std::panicking::begin_panic_handler::{{closure}}
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:657:13
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:171:18
   4: rust_begin_unwind
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:645:5
   5: core::panicking::panic_fmt
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:72:14
   6: raft::log_unstable::Unstable::must_check_outofbounds
             at /home/stn/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/a76fb6e/src/log_unstable.rs:201:13
   7: raft::log_unstable::Unstable::truncate_and_append
             at /home/stn/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/a76fb6e/src/log_unstable.rs:169:13
   8: raft::raft_log::RaftLog<T>::append
             at /home/stn/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/a76fb6e/src/raft_log.rs:395:9
   9: raft::raft_log::RaftLog<T>::maybe_append
             at /home/stn/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/a76fb6e/src/raft_log.rs:280:17
  10: raftstore::store::peer::Peer<EK,ER>::maybe_append_merge_entries
             at /home/stn/tikv/components/raftstore/src/store/peer.rs:1296:9
  11: raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::on_catch_up_logs_for_merge
             at /home/stn/tikv/components/raftstore/src/store/fsm/peer.rs:5117:15
      raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::on_significant_msg
             at /home/stn/tikv/components/raftstore/src/store/fsm/peer.rs:1616:17
  12: raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::handle_msgs
             at /home/stn/tikv/components/raftstore/src/store/fsm/peer.rs:760:49
  13: <raftstore::store::fsm::store::RaftPoller<EK,ER,T> as batch_system::batch::PollHandler<raftstore::store::fsm::peer::PeerFsm<EK,ER>,raftstore::store::fsm::store::StoreFsm<EK>>>::handle_normal
             at /home/stn/tikv/components/raftstore/src/store/fsm/store.rs:1116:9
      batch_system::batch::Poller<N,C,Handler>::poll
             at /home/stn/tikv/components/batch-system/src/batch.rs:458:27
  14: batch_system::batch::BatchSystem<N,C>::start_poller::{{closure}}
             at /home/stn/tikv/components/batch-system/src/batch.rs:589:17
      <std::thread::Builder as tikv_util::sys::thread::StdThreadBuildWrapper>::spawn_wrapper::{{closure}}
             at /home/stn/tikv/components/tikv_util/src/sys/thread.rs:438:13
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:155:18
  15: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:529:17
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:272:9
      std::panicking::try::do_call
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:552:40
      std::panicking::try
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:516:19
      std::panic::catch_unwind
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:142:14
      std::thread::Builder::spawn_unchecked_::{{closure}}
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:528:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
  16: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2015:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2015:9
      std::sys::unix::thread::Thread::new::thread_start
             at /home/stn/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:108:17
  17: start_thread
  18: clone
"] [location=/home/stn/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/a76fb6e/src/log_unstable.rs:201] [thread_name=raftstore-5-1] [thread_id=146]
```

https://tcms.pingcap.net/dashboard/executions/case/13319846

### What version of TiKV are you using?
<!-- You can run `tikv-server --version` -->

Nightly 2024-12-27
https://github.com/tikv/tikv/commit/fb67400e73c831fdae6d170c8a934f3a28f0d770

### Steps to reproduce

Run random jepsen tests.



Discussion / hints:
Another failed case: https://tcms.pingcap.net/dashboard/executions/case/13360226
Seems to caused by the concurrent `Split` and `Merge` on the same source region. 

Under further investigation, ref: https://pingcap.feishu.cn/wiki/ToRTwuOBaiqE6gkztkvcQR79npb.
Another reproduce https://tcms.pingcap.net/dashboard/executions/case/13438862, this time all TiKV panic.

Fix patch:
diff --git a/components/raftstore/src/store/async_io/write.rs b/components/raftstore/src/store/async_io/write.rs
index eedd5052bbb..b835d765d80 100644
--- a/components/raftstore/src/store/async_io/write.rs
+++ b/components/raftstore/src/store/async_io/write.rs
@@ -710,11 +710,12 @@ where
         self.batch.before_write_to_db(&self.metrics);
 
         fail_point!("raft_before_save");
+        let store_id = self.store_id;
+        fail_point!("raft_before_persist_on_store_1", store_id == 1, |_| {});
 
         let mut write_kv_time = 0f64;
         if let ExtraBatchWrite::V1(kv_wb) = &mut self.batch.extra_batch_write {
             if !kv_wb.is_empty() {
-                let store_id = self.store_id;
                 let raft_before_save_kv_on_store_3 = || {
                     fail_point!("raft_before_save_kv_on_store_3", store_id == 3, |_| {});
                 };
diff --git a/components/raftstore/src/store/peer.rs b/components/raftstore/src/store/peer.rs
index ebcf532b8ff..775fc4d81f7 100644
--- a/components/raftstore/src/store/peer.rs
+++ b/components/raftstore/src/store/peer.rs
@@ -4140,19 +4140,17 @@ where
                 }
             }
         }
-        let (mut min_m, min_c) = (min_m.unwrap_or(0), min_c.unwrap_or(0));
+        let (min_m, min_c) = (min_m.unwrap_or(0), min_c.unwrap_or(0));
         if min_m < min_c {
             warn!(
-                "min_matched < min_committed, raft progress is inaccurate";
+                "min_matched < min_committed, this is likely caused by disk IO jitters";
                 "region_id" => self.region_id,
                 "peer_id" => self.peer.get_id(),
                 "min_matched" => min_m,
                 "min_committed" => min_c,
             );
-            // Reset `min_matched` to `min_committed`, since the raft log at `min_committed`
-            // is known to be committed in all peers, all of the peers should also have
-            // replicated it
-            min_m = min_c;
+            // For region leader, matched index can be smaller than committed
+            // index if the leader's disk IO is slow.
         }
         Ok((min_m, min_c))
     }
@@ -4202,7 +4200,9 @@ where
         }
         let mut entry_size = 0;
         for entry in self.raft_group.raft.raft_log.entries(
-            min_committed + 1,
+            // entry_size depends on min_matched but admin cmd checek
+            // depends on min_committed
+            std::cmp::min(min_matched, min_committed) + 1,
             NO_LIMIT,
             GetEntriesContext::empty(false),
         )? {


Test patch:
diff --git a/components/test_raftstore/src/cluster.rs b/components/test_raftstore/src/cluster.rs
index 912b61e041a..0ac710ee739 100644
--- a/components/test_raftstore/src/cluster.rs
+++ b/components/test_raftstore/src/cluster.rs
@@ -1708,7 +1708,7 @@ impl<T: Simulator> Cluster<T> {
         }
     }
 
-    fn new_prepare_merge(&self, source: u64, target: u64) -> RaftCmdRequest {
+    pub fn new_prepare_merge(&self, source: u64, target: u64) -> RaftCmdRequest {
         let region = block_on(self.pd_client.get_region_by_id(target))
             .unwrap()
             .unwrap();
diff --git a/tests/failpoints/cases/test_merge.rs b/tests/failpoints/cases/test_merge.rs
index 68ee9c61a0a..a5a5e0f5adb 100644
--- a/tests/failpoints/cases/test_merge.rs
+++ b/tests/failpoints/cases/test_merge.rs
@@ -10,7 +10,7 @@ use std::{
     time::Duration,
 };
 
-use engine_traits::{Peekable, CF_RAFT};
+use engine_traits::{Peekable, CF_DEFAULT, CF_RAFT};
 use grpcio::{ChannelBuilder, Environment};
 use kvproto::{
     kvrpcpb::{PrewriteRequestPessimisticAction::*, *},
@@ -2243,3 +2243,80 @@ fn test_raft_log_gc_after_merge() {
     let resp = rx.recv().unwrap();
     assert!(resp.response.get_header().has_error());
 }
+
+// This case tests following scenario:
+// When the disk IO is slow or block and PrepareMerge is proposed, it is
+// possible that the leader's committed index is higher than its persisted
+// index. In this case, we should still ensure that all peers can recover
+// necessary raft logs from the CatchUpLogs phase.
+// For more information, see: https://github.com/tikv/tikv/issues/18129
+#[test]
+fn test_node_merge_with_apply_ahead_of_persist() {
+    let mut cluster = new_node_cluster(0, 3);
+    configure_for_merge(&mut cluster.cfg);
+    cluster.cfg.raft_store.cmd_batch_concurrent_ready_max_count = 32;
+    cluster.cfg.raft_store.store_io_pool_size = 1;
+
+    cluster.run();
+    let pd_client = Arc::clone(&cluster.pd_client);
+    pd_client.disable_default_operator();
+    cluster.must_transfer_leader(1, new_peer(1, 1));
+
+    cluster.must_put(b"k1", b"v1");
+    cluster.must_put(b"k3", b"v1");
+
+    let region = cluster.get_region(b"k1");
+    cluster.must_split(&region, b"k2");
+    let left = cluster.get_region(b"k1");
+    let right = cluster.get_region(b"k3");
+
+    cluster.must_put(b"k1", b"v2");
+    cluster.must_put(b"k3", b"v2");
+
+    let raft_before_save_on_store_1_fp = "raft_before_persist_on_store_1";
+    // Skip persisting to simulate raft log persist lag but not block node restart.
+    fail::cfg(raft_before_save_on_store_1_fp, "return").unwrap();
+
+    let cmd = new_put_cf_cmd(CF_DEFAULT, b"k1", b"v3");
+    let req = new_request(left.id, left.get_region_epoch().clone(), vec![cmd], false);
+    cluster
+        .call_command_on_leader(req, Duration::from_secs(1))
+        .unwrap_err();
+    let cmd = new_put_cf_cmd(CF_DEFAULT, b"k3", b"v3");
+    let req = new_request(right.id, right.get_region_epoch().clone(), vec![cmd], false);
+    cluster
+        .call_command_on_leader(req, Duration::from_secs(1))
+        .unwrap_err();
+
+    let schedule_merge_fp = "on_schedule_merge";
+    fail::cfg(schedule_merge_fp, "return()").unwrap();
+
+    // Propose merge on leader will fail with timeout due to not persist.
+    let req = cluster.new_prepare_merge(left.get_id(), right.get_id());
+    cluster
+        .call_command_on_leader(req, Duration::from_secs(1))
+        .unwrap_err();
+
+    // stop node 1, some unpersisted logs will be lost.
+    cluster.stop_node(1);
+
+    fail::remove(raft_before_save_on_store_1_fp);
+    fail::remove(schedule_merge_fp);
+
+    // Wait till merge is finished.
+    pd_client.check_merged_timeout(left.get_id(), Duration::from_secs(5));
+
+    // restart node 1 to let it apply the merge.
+    cluster.run_node(1).unwrap();
+
+    let region = cluster.get_region(b"k1");
+    let peer = region
+        .get_peers()
+        .iter()
+        .find(|p| p.store_id == 1)
+        .unwrap()
+        .clone();
+    cluster.must_transfer_leader(1, peer);
+
+    cluster.must_put(b"k1", b"v3");
+}