tikv panicked during tipocket-bank2 test

[zyguan]

Bug Report

What version of TiKV are you using?

latest release-5.0 (6e6ea0e)

What operating system and CPU are you using?

On k8s, 1C16G (maybe a little unreasonable)

Steps to reproduce

Run tipocket-bank2 on latest release-5.0 (6e6ea0e) , it failed on panic check.

2021/06/10 21:09:52 panic_check.go:85: [fatal] panic found:
        node[comp=tikv,ip=default-1623356559-tikv-2.default-1623356559-tikv-peer.tipocket-bank2.svc:20160,ns=tipocket-bank2,pod=default-1623356559-tikv-2]:
                [2021/06/10 21:08:50.570 +00:00] [UNKNOWN] [lib.rs:465] ["assertion failed: `(left == right)`\n  left: `2`,\n right: `1`"] [backtrace="stack backtrace:\n   0: tikv_util::set_panic_hook::{{closure}}\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/tikv_util/src/lib.rs:464\n   1: std::panicking::rust_panic_with_hook\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/std/src/panicking.rs:595\n   2: std::panicking::begin_panic_handler::{{closure}}\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/std/src/panicking.rs:497\n   3: std::sys_common::backtrace::__rust_end_short_backtrace\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/std/src/sys_common/backtrace.rs:141\n   4: rust_begin_unwind\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/std/src/panicking.rs:493\n   5: core::panicking::panic_fmt\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/core/src/panicking.rs:92\n   6: raftstore::store::peer::Peer<EK,ER>::post_pending_read_index_on_replica\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/peer.rs:1983\n   7: raftstore::store::peer::Peer<EK,ER>::apply_reads\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/peer.rs:2060\n      raftstore::store::peer::Peer<EK,ER>::handle_raft_ready_append\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/peer.rs:1719\n   8: raftstore::store::fsm::peer::PeerFsmDelegate<EK,ER,T>::collect_ready\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/fsm/peer.rs:925\n      <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\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/fsm/store.rs:829\n   9: batch_system::batch::Poller<N,C,Handler>::poll\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/batch-system/src/batch.rs:325\n  10: batch_system::batch::BatchSystem<N,C>::spawn::{{closure}}\n             at home/jenkins/agent/workspace/build-tikv/tikv/components/batch-system/src/batch.rs:399\n      std::sys_common::backtrace::__rust_begin_short_backtrace\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/sys_common/backtrace.rs:125\n  11: std::thread::Builder::spawn_unchecked::{{closure}}::{{closure}}\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/thread/mod.rs:474\n      <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/panic.rs:322\n      std::panicking::try::do_call\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/panicking.rs:379\n      std::panicking::try\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/panicking.rs:343\n      std::panic::catch_unwind\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/panic.rs:396\n      std::thread::Builder::spawn_unchecked::{{closure}}\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/std/src/thread/mod.rs:473\n      core::ops::function::FnOnce::call_once{{vtable.shim}}\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/core/src/ops/function.rs:227\n  12: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/alloc/src/boxed.rs:1484\n      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35/library/alloc/src/boxed.rs:1484\n      std::sys::unix::thread::Thread::new::thread_start\n             at rustc/bc39d4d9c514e5fdb40a5782e6ca08924f979c35//library/std/src/sys/unix/thread.rs:71\n  13: <unknown>\n  14: clone\n"] [location=/home/jenkins/agent/workspace/build-tikv/tikv/components/raftstore/src/store/peer.rs:1983] [thread_name=raftstore-5-1]

http://fileserver.pingcap.net/download/pingcap/qa/draft/tikv-panic.log.gz

What did you expect?

The test exit without error.

What did happened?

TiKV panicked.

[cosven]

/type bug
/severity critical

[sticnarf]

The only chance that cmds.len() becomes 2 is https://github.com/tikv/tikv/blob/61265d3898/components/raftstore/src/store/peer.rs#L2739.

So the trigger condition is:

1. There is a pending read index
2. When the peer is a leader and in the lease, it receives another read index.
3. After the lease expires, the peer receives the third read index request.
4. The peer loses its leadership
5. The response of the first read index is lost. And then we receive the response of the third read index. Then, we should be able to trigger the panic.

I am still having difficulties in writing a unit test to reproduce it......

The solution is to forbid the optimization at https://github.com/tikv/tikv/blob/61265d3898/components/raftstore/src/store/peer.rs#L2739 for requests that contain memory lock checking.