[dynamic regions] tiflash panic due to data error

[dbsid]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

tiup bench ch -H 172.16.5.140 -P 4000 -D tpcc prepare

during data preparation, enable tiflash replicas

ALTER DATABASE tpcc SET TIFLASH REPLICA 2;

2. What did you expect to see? (Required)

no tiflash crash

3. What did you see instead (Required)

tiflash crash

[2023/05/30 14:58:00.011 +08:00] [ERROR] [Exception.cpp:90] ["Code: 9008, e.displayText() = DB::Exception: Raw TiDB PK: 038000000000000263038000000000017801, Prewrite ts: 441824118259581985 can not found in default cf for key: 7480000000000000FF795F720380000000FF0000026303800000FF0000017801000000FCF9DE534E2797FB83, e.what() = DB::Exception, Stack trace:\n\n\n       0x1c206ce\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [tiflash+29492942]\n                \tdbms/src/Common/Exception.h:46\n       0x7ff0aa0\tDB::RegionData::readDataByWriteIt(std::__1::__map_const_iterator<std::__1::__tree_const_iterator<std::__1::__value_type<std::__1::pair<DB::RawTiDBPK, unsigned long>, std::__1::tuple<std::__1::shared_ptr<DB::StringObject<true> const>, std::__1::shared_ptr<DB::StringObject<false> const>, DB::RecordKVFormat::InnerDecodedWriteCFValue> >, std::__1::__tree_node<std::__1::__value_type<std::__1::pair<DB::RawTiDBPK, unsigned long>, std::__1::tuple<std::__1::shared_ptr<DB::StringObject<true> const>, std::__1::shared_ptr<DB::StringObject<false> const>, DB::RecordKVFormat::InnerDecodedWriteCFValue> >, void*>*, long> > const&, bool) const [tiflash+134154912]\n                \tdbms/src/Storages/Transaction/RegionData.cpp:136\n       0x7fb4329\tDB::ReadRegionCommitCache(std::__1::shared_ptr<DB::Region> const&, bool) [tiflash+133907241]\n                \tdbms/src/Storages/Transaction/PartitionStreams.cpp:289\n       0x7fb492e\tDB::RegionTable::writeBlockByRegion(DB::Context&, DB::RegionPtrWithBlock const&, std::__1::vector<std::__1::tuple<DB::RawTiDBPK, unsigned char, unsigned long, std::__1::shared_ptr<DB::StringObject<false> const> >, std::__1::allocator<std::__1::tuple<DB::RawTiDBPK, unsigned char, unsigned long, std::__1::shared_ptr<DB::StringObject<false> const> > > >&, std::__1::shared_ptr<DB::Logger> const&, bool) [tiflash+133908782]\n                \tdbms/src/Storages/Transaction/PartitionStreams.cpp:352\n       0x7fdf08d\tDB::Region::handleWriteRaftCmd(DB::WriteCmdsView const&, unsigned long, unsigned long, DB::TMTContext&) [tiflash+134082701]\n                \tdbms/src/Storages/Transaction/Region.cpp:721\n       0x7f9d8ee\tDB::KVStore::handleWriteRaftCmd(DB::WriteCmdsView const&, unsigned long, unsigned long, unsigned long, DB::TMTContext&) const [tiflash+133814510]\n                \tdbms/src/Storages/Transaction/KVStore.cpp:297\n       0x7fbd075\tHandleWriteRaftCmd [tiflash+133943413]\n                \tdbms/src/Storages/Transaction/ProxyFFI.cpp:97\n  0x7ff9ca3feb98\t_$LT$engine_store_ffi..observer..TiFlashObserver$LT$T$C$ER$GT$$u20$as$u20$raftstore..coprocessor..QueryObserver$GT$::post_exec_query::h7baebf297f3c710d [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+24021912]\n  0x7ff9cb315c1d\traftstore::store::fsm::apply::ApplyDelegate$LT$EK$GT$::apply_raft_cmd::h25535f78b2e0a609 [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+39844893]\n  0x7ff9cb32f598\traftstore::store::fsm::apply::ApplyDelegate$LT$EK$GT$::process_raft_cmd::h61e8e50fe51b205f [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+39949720]\n  0x7ff9cb334ee4\traftstore::store::fsm::apply::ApplyDelegate$LT$EK$GT$::handle_raft_committed_entries::h5998616c7ccbd00a [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+39972580]\n  0x7ff9cb3061cc\traftstore::store::fsm::apply::ApplyFsm$LT$EK$GT$::handle_apply::hdf9cbdff9eae6fb5 [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+39780812]\n  0x7ff9cb30a721\traftstore::store::fsm::apply::ApplyFsm$LT$EK$GT$::handle_tasks::hf5349c3a9c0f2237 [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+39798561]\n  0x7ff9ca4e298e\t_$LT$raftstore..store..fsm..apply..ApplyPoller$LT$EK$GT$$u20$as$u20$batch_system..batch..PollHandler$LT$raftstore..store..fsm..apply..ApplyFsm$LT$EK$GT$$C$raftstore..store..fsm..apply..ControlFsm$GT$$GT$::handle_normal::h95c5548f3d56678b [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+24955278]\n  0x7ff9ca44f783\tbatch_system::batch::Poller$LT$N$C$C$C$Handler$GT$::poll::h55f624a09f386174 [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+24352643]\n  0x7ff9ca546c18\tstd::sys_common::backtrace::__rust_begin_short_backtrace::h16cb33ef4f63f5a9 [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+25365528]\n  0x7ff9ca5906fe\tcore::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h3daa0229b294447f [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+25667326]\n  0x7ff9cbad42f5\tstd::sys::unix::thread::Thread::new::thread_start::hd2791a9cabec1fda [[libtiflash_proxy.so](http://libtiflash_proxy.so/)+47964917]\n                \t/rustc/96ddd32c4bfb1d78f0cd03eb068b1710a8cebeef/library/std/src/sys/unix/[thread.rs:108](http://thread.rs:108/)\n  0x7ff9c89e5802\tstart_thread [libc.so.6+653314]\n  0x7ff9c8985314\t__GI___clone [libc.so.6+258836]"] [source="DB::EngineStoreApplyRes DB::HandleWriteRaftCmd(const DB::EngineStoreServerWrap *, DB::WriteCmdsView, DB::RaftCmdHeader)"] [thread_id=129]

4. What is your TiFlash version? (Required)

[CalvinNeo]

Find key on tikv-3 failed

[root@tc-tikv-3 /]# ./tikv-ctl --host tc-tikv-3.tc-tikv-peer.mutiple-rocksdb-bpv89.svc:20160 print -c write -k "zt\200\000\000\000\000\000\000\377y_r\003\200\000\000\000\377\000\000\002c\003\200\000\000\377\000\000\001x\001\000\000\000\374\371\336SN'\227\373\203"
DebugClient::get: RpcFailure: 5-NOT_FOUND Not found region containing [116, 128, 0, 0, 0, 0, 0, 0, 255, 121, 95, 114, 3, 128, 0, 0, 0, 255, 0, 0, 2, 99, 3, 128, 0, 0, 255, 0, 0, 1, 120, 1, 0, 0, 0, 252, 249, 222, 83, 78, 39, 151, 251, 131]
[root@tc-tikv-3 /]# ./tikv-ctl --host tc-tikv-3.tc-tikv-peer.mutiple-rocksdb-bpv89.svc:20160 print -c write -k "t\200\000\000\000\000\000\000\377y_r\003\200\000\000\000\377\000\000\002c\003\200\000\000\377\000\000\001x\001\000\000\000\374\371\336SN'\227\373\203"
DebugClient::get: RpcFailure: 5-NOT_FOUND Not found region containing [128, 0, 0, 0, 0, 0, 0, 255, 121, 95, 114, 3, 128, 0, 0, 0, 255, 0, 0, 2, 99, 3, 128, 0, 0, 255, 0, 0, 1, 120, 1, 0, 0, 0, 252, 249, 222, 83, 78, 39, 151, 251, 131]

[CalvinNeo]

Find key on tikv-8 failed

[root@tc-tikv-8 /]# /tikv-ctl --host tc-tikv-8.tc-tikv-peer.mutiple-rocksdb-bpv89.svc:20160 print -c write -k "t\200\000\000\000\000\000\000\377y_r\003\200\000\000\000\377\000\000\002c\003\200\000\000\377\000\000\001x\^C1\000\000\000\374\371\336SN'\227\373\203"
DebugClient::get: RpcFailure: 14-UNAVAILABLE failed to connect to all addresses
[root@tc-tikv-8 /]# /tikv-ctl --host tc-tikv-8.tc-tikv-peer.mutiple-rocksdb-bpv89.svc:20160 print -c write -k "zt\200\000\000\000\000\000\000\377y_r\003\200\000\000\000\377\000\000\002c\003\200\000\000\377\000\000\001x\^C1\000\000\000\374\371\336SN'\227\373\203"
DebugClient::get: RpcFailure: 14-UNAVAILABLE failed to connect to all addresses

[overvenus]

In raftstore v2, a snapshot may contains data written by newer raft logs (whose indexes are larger than snapshot index).

A possible fix for proxy:

1. apply the snapshot without checking mvcc consistency.
2. issue a read index.
3. wait proxy applied to the read index.
4. take a snapshot and ingest data to tilfash.

[CalvinNeo]

In raftstore v2, a snapshot may contains data written by newer raft logs (whose indexes are larger than snapshot index).

A possible fix for proxy:

1. apply the snapshot without checking mvcc consistency.
2. issue a read index.
3. wait proxy applied to the read index.
4. take a snapshot and ingest data to tilfash.

ReadIndex is a network request which introduce a timeout state. It is not a good practice to do block waiting in this case, since applying snapshot is single-threaded. Meanwhile, we can not set a proper timeout for this loop, because we still can't just neglect the potential error when timeout.

[CalvinNeo]

See also #7791

[CalvinNeo]

Due to #7791, the whole checking system is closed temporarily. We also reduce the severity for now.
A complete solution will keep snapshot from being deleted before all orphan keys being handled. This is an intrusive modification to TiKV, and also complicated, we will do that or reconsider later.

[JaySon-Huang]

Close as the "Dynamic Region" aka "Partitioned Raft KV" has been stopped for a long time