TiKV running over 2 years may panic

[you06]

Bug Report

What version of TiKV are you using?

nightly(this case also appears on v3.0.5)

What operating system and CPU are you using?

Steps to reproduce

Running TiKV for 795 days, then some RPC failure may cause panic.

A simple reproduce using Chaos Mesh:

tiup playground --tiflash=0 --monitor=false
sudo kill {pid_of_pd}
sudo ./watchmaker -pid {pid_of_tikv} -sec_delta 68719436 -clk_ids=CLOCK_MONOTONIC

What did you expect?

No fatal error with TiKV.

What did happened?

TiKV quits with fatal error.

[2022/02/08 20:32:34.418 +08:00] [ERROR] [util.rs:419] ["request failed, retry"] [err_code=KV:PD:Unknown] [err="Other(\"[components/pd_client/src/tso.rs:85]: TimestampRequest channel is closed\")"]
[2022/02/08 20:32:34.418 +08:00] [ERROR] [util.rs:419] ["request failed, retry"] [err_code=KV:PD:Unknown] [err="Other(\"[components/pd_client/src/tso.rs:85]: TimestampRequest channel is closed\")"]
[2022/02/08 20:32:34.418 +08:00] [ERROR] [util.rs:419] ["request failed, retry"] [err_code=KV:PD:Unknown] [err="Other(\"[components/pd_client/src/tso.rs:85]: TimestampRequest channel is closed\")"]
[2022/02/08 20:32:34.418 +08:00] [ERROR] [util.rs:419] ["request failed, retry"] [err_code=KV:PD:Unknown] [err="Other(\"[components/pd_client/src/tso.rs:85]: TimestampRequest channel is closed\")"]
[2022/02/08 20:32:34.421 +08:00] [FATAL] [lib.rs:465] ["index out of bounds: the len is 6 but the index is 6"] [backtrace="   0: tikv_util::set_panic_hook::{{closure}}\n             at /home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tikv/components/tikv_util/src/lib.rs:464:18\n   1: std::panicking::rust_panic_with_hook\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panicking.rs:626:17\n   2: std::panicking::begin_panic_handler::{{closure}}\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panicking.rs:519:13\n   3: std::sys_common::backtrace::__rust_end_short_backtrace\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/sys_common/backtrace.rs:141:18\n   4: rust_begin_unwind\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panicking.rs:515:5\n   5: core::panicking::panic_fmt\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/core/src/panicking.rs:92:14\n   6: core::panicking::panic_bounds_check\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/core/src/panicking.rs:69:5\n   7: <usize as core::slice::index::SliceIndex<[T]>>::index_mut\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/core/src/slice/index.rs:190:14\n      core::slice::index::<impl core::ops::index::IndexMut<I> for [T]>::index_mut\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/core/src/slice/index.rs:26:9\n      <alloc::vec::Vec<T,A> as core::ops::index::IndexMut<I>>::index_mut\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/alloc/src/vec/mod.rs:2445:9\n      tokio_timer::wheel::Wheel<T>::insert\n             at /rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:114:9\n      tokio_timer::timer::Timer<T,N>::add_entry\n             at /rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/timer/mod.rs:324:15\n   8: tokio_timer::timer::Timer<T,N>::process_queue\n             at /rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/timer/mod.rs:301:21\n   9: <tokio_timer::timer::Timer<T,N> as tokio_executor::park::Park>::park\n             at /rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/timer/mod.rs:361:9\n      tokio_timer::timer::Timer<T,N>::turn\n             at /rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/timer/mod.rs:256:21\n  10: tikv_util::timer::start_global_timer::{{closure}}\n             at /home/jenkins/agent/workspace/optimization-build-tidb-linux-amd/go/src/github.com/pingcap/tikv/components/tikv_util/src/timer.rs:98:17\n  11: std::sys_common::backtrace::__rust_begin_short_backtrace\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/sys_common/backtrace.rs:125:18\n  12: std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/thread/mod.rs:476:17\n  13: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panic.rs:347:9\n  14: std::panicking::try::do_call\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panicking.rs:401:40\n      std::panicking::try\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panicking.rs:365:19\n      std::panic::catch_unwind\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/panic.rs:434:14\n      std::thread::Builder::spawn_unchecked::{{closure}}\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/thread/mod.rs:475:30\n      core::ops::function::FnOnce::call_once{{vtable.shim}}\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/core/src/ops/function.rs:227:5\n  15: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/alloc/src/boxed.rs:1572:9\n      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/alloc/src/boxed.rs:1572:9\n      std::sys::unix::thread::Thread::new::thread_start\n             at /rustc/2faabf579323f5252329264cc53ba9ff803429a3/library/std/src/sys/unix/thread.rs:91:17\n  16: start_thread\n  17: __GI___clone\n"] [location=/rust/registry/src/github.com-1ecc6299db9ec823/tokio-timer-0.2.13/src/wheel/mod.rs:114] [thread_name=timer]

[you06]

Because all the versions of TiKV use the deprecated tokio-timer, the bug exists in all versions.

tikv/Cargo.toml

Line 152 in ddec018

tokio-timer = "0.2"

The problem comes here(fixed in the latest tokio).

fn level_for(elapsed: u64, when: u64) -> usize {
    const SLOT_MASK: u64 = (1 << 6) - 1;

    // Mask in the trailing bits ignored by the level calculation in order to cap
    // the possible leading zeros
    let masked = elapsed ^ when | SLOT_MASK;

    let leading_zeros = masked.leading_zeros() as usize;
    let significant = 63 - leading_zeros;
    significant / 6
}

In which, elapsed stands for the elapsed time since the process is started, and when stands for the expired wake-up time since the process is started. Suppose elapsed is 2 ^ 36 - 1 and when is 2 ^ 36, we'll get masked with 27 leading zeros, and the result level is 6 which causes the "index out of bounds" error.

[Lily2025]

/severity Critical

[youjiali1995]

interesting

[alex-quan-001]

@you06 Any plans to upgrade to use the replacement module?

https://crates.io/crates/tokio-timer

Note: This crate is deprecated in tokio 0.2.x and has been moved into tokio::time behind the time feature flag.

We have so many third-party library dependencies that have not updated long time, need to be evaluated for upgrading to a newer stable version. We should schedule a 3rd-party library upgrade plan in subsequent sprint. @zhouqiang-cl

[you06]

@you06 Any plans to upgrade to use the replacement module?

As you mentioned, tokio-timer is now a feature of tokio, I'm afraid there are some differences in the usage, liketokio::timer is relied on the tokio's runtime. On the other hand, yatp does not support the time feature, so the fix needs to be discussed.

[shonge]

Do we have a workaround?

[you06]

Do we have a workaround?

Rolling restarting TiKV cluster every 2 years.

[BusyJay]

What we want is a timer with customizable now implementation. Perhaps we can just maintain our own crate without depending on specific runtime.

[you06]

@BusyJay For an easy approach, what about futures-timer?. CDC is using it, and I'm currently trying to replace tokio-timer with it.

tikv/components/cdc/Cargo.toml

Line 56 in 3433be9

futures-timer = "3.0"

[BusyJay]

No, it doesn't support custom new.

[you06]

@BusyJay Sorry I don't understand the relationship between custom now and this issue. Even there is a custom now in TiKV, the incorrect time wheel calculation can still lead to panic. Custom now looks like an enhancement to me. May you explain what needs to be replaced and how to fix this issue?

[BusyJay]

A customized new will not fix the issue. What I mean is new implementations should allow customizing new, because TiKV needs a steady timer to guarantee correctness.

[you06]

@BusyJay Do you think it's necessary to fork tokio-timer and fix this bug so that we can do a hotfix? We can replace this when a self-maintained time crate is available in the future.

[BusyJay]

LGTM