Skip to content

tikv panic in on_raft_gc_log_tick after region is merged #17840

@glorv

Description

@glorv

Bug Report

"[2024/11/14 01:40:44.755 +00:00] [FATAL] [lib.rs:509] ["called `Option::unwrap()` on a `None` value"] [backtrace="   0: tikv_util::set_panic_hook::{{closure}}
             at tikv/components/tikv_util/src/lib.rs:508:18
   1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2032:9
      std::panicking::rust_panic_with_hook
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:692:13
   2: std::panicking::begin_panic_handler::{{closure}}
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:577:13
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:137:18
   4: rust_begin_unwind
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:575:5
   5: core::panicking::panic_fmt
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:65:14
   6: core::panicking::panic
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:114:5
   7: raftstore::store::entry_storage::EntryStorage<EK,ER>::term
   8: <raftstore::store::peer_storage::PeerStorage<EK,ER> as raft::storage::Storage>::term
             at tikv/components/raftstore/src/store/peer_storage.rs:273:9
      raft::raft_log::RaftLog<T>::term
             at root/.cargo/git/checkouts/raft-rs-42b8049ef2e3af07/2357cb2/src/raft_log.rs:131:18
   9: raftstore::store::peer::Peer<EK,ER>::get_index_term
             at tikv/components/raftstore/src/store/peer.rs:1307:15
      raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::on_raft_gc_log_tick
             at tikv/components/raftstore/src/store/fsm/peer.rs:5456:20
  10: raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::handle_msgs
             at tikv/components/raftstore/src/store/fsm/peer.rs:674:48
  11: <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 tikv/components/raftstore/src/store/fsm/store.rs:971:9
  12: batch_system::batch::Poller<N,C,Handler>::poll
             at tikv/components/batch-system/src/batch.rs:430:27
  13: batch_system::batch::BatchSystem<N,C>::start_poller::{{closure}}
             at tikv/components/batch-system/src/batch.rs:600:17
      <std::thread::Builder as tikv_util::sys::thread::StdThreadBuildWrapper>::spawn_wrapper::{{closure}}
             at tikv/components/tikv_util/src/sys/thread.rs:415:23
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:121:18
  14: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:551:17
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:271:9
      std::panicking::try::do_call
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:483:40
      std::panicking::try
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:447:19
      std::panic::catch_unwind
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:137:14
      std::thread::Builder::spawn_unchecked_::{{closure}}
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/mod.rs:550:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:513:5
  15: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2000:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/boxed.rs:2000:9
      std::sys::unix::thread::Thread::new::thread_start
             at root/.rustup/toolchains/nightly-2022-11-15-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:108:17
  16: start_thread
  17: __clone3
"] [location=/tikv/components/raftstore/src/store/entry_storage.rs:952] [thread_name=raftstore-1693-0]",

related logs before this panic:

"[2024/11/14 01:40:44.469 +00:00] [INFO] [pd.rs:1567] [\"try to merge\"] [merge=\"target { id: 138832049 start_key: ? end_key: ? region_epoch { conf_ver: 7127 version: 992958 } peers { id: 138832050 store_id: 205 } peers { id: 138832052 store_id: 431 } peers { id: 540299072 store_id: 1693 } }\"] [region_id=139238551]",
  "[2024/11/14 01:40:44.480 +00:00] [INFO] [apply.rs:1612] [\"execute admin command\"] [command=\"cmd_type: PrepareMerge prepare_merge { min_index: 305 target { id: 138832049 start_key: ? end_key: ? region_epoch { conf_ver: 7127 version: 992958 } peers { id: 138832050 store_id: 205 } peers { id: 138832052 store_id: 431 } peers { id: 540299072 store_id: 1693 } } }\"] [index=305] [term=188] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.486 +00:00] [INFO] [endpoint.rs:177] [\"region met split/merge command, stop tracking since key range changed, wait for re-register\"] [req_type=PrepareMerge]",
  "[2024/11/14 01:40:44.486 +00:00] [INFO] [endpoint.rs:414] [\"deregister observe region\"] [observe_id=ObserveId(12870)] [region_id=139238551] [store_id=Some(1693)]",
  "[2024/11/14 01:40:44.486 +00:00] [INFO] [endpoint.rs:337] [\"register observe region\"] [region=\"id: 139238551 start_key: ? end_key: ? region_epoch { conf_ver: 7182 version: 992922 } peers { id: 1010311597 store_id: 1693 } peers { id: 1292018290 store_id: 205 } peers { id: 1292018291 store_id: 431 }\"]",
  "[2024/11/14 01:40:44.497 +00:00] [INFO] [apply.rs:2764] [\"asking delegate to stop\"] [source_region_id=139238551] [peer_id=540299072] [region_id=138832049]",
  "[2024/11/14 01:40:44.497 +00:00] [INFO] [apply.rs:3798] [\"source logs are all applied now\"] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.497 +00:00] [INFO] [apply.rs:3723] [\"remove delegate from apply delegates\"] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.497 +00:00] [INFO] [router.rs:345] [\"[region 139238551] shutdown mailbox\"]",
  "[2024/11/14 01:40:44.499 +00:00] [INFO] [apply.rs:2786] [\"execute CommitMerge\"] [source_region=\"id: 139238551 start_key: ? end_key: ? region_epoch { conf_ver: 7182 version: 992922 } peers { id: 1010311597 store_id: 1693 } peers { id: 1292018290 store_id: 205 } peers { id: 1292018291 store_id: 431 }\"] [index=263] [term=168] [entries=1] [commit=305] [peer_id=540299072] [region_id=138832049]",
  "[2024/11/14 01:40:44.502 +00:00] [INFO] [util.rs:1459] [\"reset safe_ts due to merge\"] [peer_id=540299072] [region_id=138832049] [safe_ts=453915034481075508] [target_safe_ts=453915034481075508] [source_safe_ts=453915035398572863]",
  "[2024/11/14 01:40:44.502 +00:00] [INFO] [peer.rs:5626] [\"require updating max ts\"] [initial_status=721556491646] [region_id=138832049]",
  "[2024/11/14 01:40:44.502 +00:00] [INFO] [peer.rs:4726] [\"merge finished\"] [target_region=\"Some(id: 138832049 start_key: ? end_key: ? region_epoch { conf_ver: 7127 version: 992958 } peers { id: 138832050 store_id: 205 } peers { id: 138832052 store_id: 431 } peers { id: 540299072 store_id: 1693 })\"] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.502 +00:00] [INFO] [peer.rs:3574] [\"delays destroy\"] [reason=UnFlushLogGc] [merged_by_target=true] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.502 +00:00] [INFO] [pd.rs:1707] [\"succeed to update max timestamp\"] [region_id=138832049]",
  "[2024/11/14 01:40:44.510 +00:00] [INFO] [peer.rs:3584] [\"starts destroy\"] [merged_by_target=true] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.510 +00:00] [INFO] [peer.rs:1459] [\"begin to destroy\"] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.510 +00:00] [INFO] [pd.rs:1637] [\"remove peer statistic record in pd\"] [region_id=139238551]",
  "[2024/11/14 01:40:44.510 +00:00] [INFO] [peer_storage.rs:1020] [\"finish clear peer meta\"] [takes=2.138µs] [raft_key=1] [apply_key=1] [meta_key=1] [region_id=139238551]",
  "[2024/11/14 01:40:44.510 +00:00] [INFO] [endpoint.rs:414] [\"deregister observe region\"] [observe_id=ObserveId(12873)] [region_id=139238551] [store_id=Some(1693)]",
  "[2024/11/14 01:40:44.512 +00:00] [WARN] [scanner.rs:95] [\"resolved_ts scan get snapshot failed\"] [err=\"Other(\\\"scan task cancelled\\\")\"]",
  "[2024/11/14 01:40:44.518 +00:00] [INFO] [peer.rs:1563] [\"peer destroy itself\"] [keep_data=true] [clean=true] [takes=8.271467ms] [peer_id=1010311597] [region_id=139238551]",
  "[2024/11/14 01:40:44.518 +00:00] [INFO] [router.rs:345] [\"[region 139238551] shutdown mailbox\"]",

What version of TiKV are you using?

v6.5.4

What operating system and CPU are you using?

Steps to reproduce

What did you expect?

What did happened?

Metadata

Metadata

Assignees

No one assigned

    Labels

    affects-5.4This bug affects the 5.4.x(LTS) versions.affects-6.1This bug affects the 6.1.x(LTS) versions.affects-6.5This bug affects the 6.5.x(LTS) versions.affects-7.1This bug affects the 7.1.x(LTS) versions.affects-7.5This bug affects the 7.5.x(LTS) versions.affects-8.1This bug affects the 8.1.x(LTS) versions.affects-8.5This bug affects the 8.5.x(LTS) versions.impact/panicreport/customerCustomers have encountered this bug.severity/majortype/bugThe issue is confirmed as a bug.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions