tikv panic for "assertion failed: row.lock.is_none()"

[seiya-annie]

Bug Report

What version of TiKV are you using?

["Git Commit Hash: b7103fa"] [thread_id=1]

What operating system and CPU are you using?

Steps to reproduce

bank-tbls-pessimistic-inplace-follower-neterr
txn-mode=pessimistic, follower-read=true
run bank workload,
injuct network fail
params:
--txn-mode=pessimistic --force-reinstall=true --update-in-place=true
--follower-read=true
--nemesis=schedules,partition-pd-leader,partition-half,partition-ring
--read-lock=update --os=image --time-limit=600 --version=master
--workload=bank-multitable --init-sql='set
@@tidb_enable_mutation_checker=1, @@tidb_txn_assertion_level=strict,
@@tidb_constraint_check_in_place_pessimistic=off'

What did you expect?

pass

What did happened?

[2024/04/11 19:01:19.274 +00:00] [FATAL] [lib.rs:477] ["assertion failed: row.lock.is_none()"] [backtrace="   0: tikv_util::set_panic_hook::{{closure}}
             at /workspace/source/tikv/components/tikv_util/src/lib.rs:476:18
   1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
             at /root/.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 /root/.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 /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:649:13
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at /root/.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 /root/.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 /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:72:14
   6: core::panicking::panic
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panicking.rs:144:5
   7: resolved_ts::cmd::group_row_changes
             at /workspace/source/tikv/components/resolved_ts/src/cmd.rs:224:25
      resolved_ts::cmd::ChangeLog::encode_change_log::{{closure}}
             at /workspace/source/tikv/components/resolved_ts/src/cmd.rs:62:57
      core::iter::adapters::map::map_fold::{{closure}}
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/iter/adapters/map.rs:85:28
      core::iter::traits::iterator::Iterator::fold
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/iter/traits/iterator.rs:2640:21
      <core::iter::adapters::map::Map<I,F> as core::iter::traits::iterator::Iterator>::fold
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/iter/adapters/map.rs:125:9
      core::iter::traits::iterator::Iterator::for_each
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/iter/traits/iterator.rs:858:9
      alloc::vec::Vec<T,A>::extend_trusted
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec/mod.rs:2923:17
      <alloc::vec::Vec<T,A> as alloc::vec::spec_extend::SpecExtend<T,I>>::spec_extend
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec/spec_extend.rs:26:9
      <alloc::vec::Vec<T> as alloc::vec::spec_from_iter_nested::SpecFromIterNested<T,I>>::from_iter
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec/spec_from_iter_nested.rs:62:9
      alloc::vec::in_place_collect::<impl alloc::vec::spec_from_iter::SpecFromIter<T,I> for alloc::vec::Vec<T>>::from_iter
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec/in_place_collect.rs:233:20
      <alloc::vec::Vec<T> as core::iter::traits::collect::FromIterator<T>>::from_iter
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec/mod.rs:2791:9
      core::iter::traits::iterator::Iterator::collect
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/iter/traits/iterator.rs:2054:9
      resolved_ts::cmd::ChangeLog::encode_change_log
             at /workspace/source/tikv/components/resolved_ts/src/cmd.rs:76:14
   8: resolved_ts::endpoint::Endpoint<T,E,S>::handle_change_log
             at /workspace/source/tikv/components/resolved_ts/src/endpoint.rs:883:32
      <resolved_ts::endpoint::Endpoint<T,E,S> as tikv_util::worker::pool::Runnable>::run
             at /workspace/source/tikv/components/resolved_ts/src/endpoint.rs:1132:46
      tikv_util::worker::pool::Worker::start_with_timer_impl::{{closure}}
             at /workspace/source/tikv/components/tikv_util/src/worker/pool.rs:517:25
   9: <tracker::tls::TrackedFuture<F> as core::future::future::Future>::poll::{{closure}}
             at /workspace/source/tikv/components/tracker/src/tls.rs:64:23
      std::thread::local::LocalKey<T>::try_with
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:270:16
      std::thread::local::LocalKey<T>::with
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:246:9
      <tracker::tls::TrackedFuture<F> as core::future::future::Future>::poll
             at /workspace/source/tikv/components/tracker/src/tls.rs:62:27
      <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at /workspace/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-util-0.3.15/src/future/future/map.rs:55:37
      <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at /workspace/.cargo/registry/src/index.crates.io-6f17d22bba15001f/futures-util-0.3.15/src/lib.rs:93:13
      yatp::task::future::RawTask<F>::poll
             at /workspace/.cargo/git/checkouts/yatp-e704b73c3ee279b6/793be4d/src/task/future.rs:59:9
  10: yatp::task::future::TaskCell::poll
             at /workspace/.cargo/git/checkouts/yatp-e704b73c3ee279b6/793be4d/src/task/future.rs:103:9
      <yatp::task::future::Runner as yatp::pool::runner::Runner>::handle
             at /workspace/.cargo/git/checkouts/yatp-e704b73c3ee279b6/793be4d/src/task/future.rs:387:20
  11: <tikv_util::yatp_pool::YatpPoolRunner<T> as yatp::pool::runner::Runner>::handle
             at /workspace/source/tikv/components/tikv_util/src/yatp_pool/mod.rs:198:24
      yatp::pool::worker::WorkerThread<T,R>::run
             at /workspace/.cargo/git/checkouts/yatp-e704b73c3ee279b6/793be4d/src/pool/worker.rs:48:13
      yatp::pool::builder::LazyBuilder<T>::build::{{closure}}
             at /workspace/.cargo/git/checkouts/yatp-e704b73c3ee279b6/793be4d/src/pool/builder.rs:114:25
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys_common/backtrace.rs:155:18
  12: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /root/.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 /root/.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 /root/.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 /root/.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 /root/.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 /root/.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 /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
  13: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /root/.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 /root/.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 /root/.rustup/toolchains/nightly-2023-12-28-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/sys/unix/thread.rs:108:17
  14: start_thread
  15: clone
"] [location=components/resolved_ts/src/cmd.rs:224] [thread_name=resolved-ts-0] [thread_id=75]

[cfzjywxk]

It seems to be related to the pipelined dml implementation, which breaks the constraint Prewrite Lock would be written at most one time. Need more investigations.

Verfied the pipelined-dml is not enabled in this case

[zhangjinpeng87]

@cfzjywxk @seiya-annie Did you tested "follwer-read=false" case? Is this because follower-read?

[cfzjywxk]

@cfzjywxk @seiya-annie Did you tested "follwer-read=false" case? Is this because follower-read?

@zhangjinpeng87

This issue has also occurred in non-follower-read Jepsen test jobs. The panic occurs during the observation of the apply result process in resolved-ts. It appears that the Requests of RaftCmdRequest involving a lock write for the same key twice which does not comply with the transaction protocol, indicating a correctness issue.

Currently, we have added logging before the assertion. After reproducing the issue, we can further examine the logs to determine which transaction's write operation caused this situation.