From 04bf517203e4df2850a402aec51432ef8847e4b6 Mon Sep 17 00:00:00 2001 From: Calvin Neo Date: Thu, 15 Jun 2023 18:11:10 +0800 Subject: [PATCH] Add log when handling a snapshot with invalid data (#7581) ref pingcap/tiflash#7568 --- .../DeltaMerge/SSTFilesToBlockInputStream.cpp | 12 ++++++- dbms/src/Storages/Transaction/SSTReader.cpp | 8 ++++- dbms/src/Storages/Transaction/SSTReader.h | 7 ++++ .../Transaction/tests/gtest_new_kvstore.cpp | 34 ++++++++++++++++++- 4 files changed, 58 insertions(+), 3 deletions(-) diff --git a/dbms/src/Storages/DeltaMerge/SSTFilesToBlockInputStream.cpp b/dbms/src/Storages/DeltaMerge/SSTFilesToBlockInputStream.cpp index 54700575698..5237bc088dc 100644 --- a/dbms/src/Storages/DeltaMerge/SSTFilesToBlockInputStream.cpp +++ b/dbms/src/Storages/DeltaMerge/SSTFilesToBlockInputStream.cpp @@ -261,7 +261,17 @@ Block SSTFilesToBlockInputStream::readCommitedBlock() if (e.code() == ErrorCodes::ILLFORMAT_RAFT_ROW) { // br or lighting may write illegal data into tikv, stop decoding. - LOG_WARNING(log, "Got error while reading region committed cache: {}. Stop decoding rows into DTFiles and keep uncommitted data in region.", e.displayText()); + const auto & start_key = region->getMetaRegion().start_key(); + const auto & end_key = region->getMetaRegion().end_key(); + LOG_WARNING(log, "Got error while reading region committed cache: {}. Stop decoding rows into DTFiles and keep uncommitted data in region." + "region_id: {}, applied_index: {}, version: {}, conf_version {}, start_key: {}, end_key: {}", + e.displayText(), + region->id(), + region->appliedIndex(), + region->version(), + region->confVer(), + Redact::keyToDebugString(start_key.data(), start_key.size()), + Redact::keyToDebugString(end_key.data(), end_key.size())); // Cancel the decoding process. // Note that we still need to scan data from CFs and keep them in `region` is_decode_cancelled = true; diff --git a/dbms/src/Storages/Transaction/SSTReader.cpp b/dbms/src/Storages/Transaction/SSTReader.cpp index 6aef966738c..43023d0d03e 100644 --- a/dbms/src/Storages/Transaction/SSTReader.cpp +++ b/dbms/src/Storages/Transaction/SSTReader.cpp @@ -32,6 +32,11 @@ bool MonoSSTReader::remained() const auto key = buffToStrView(proxy_helper->sst_reader_interfaces.fn_key(inner, type)); if (!end.empty() && key >= end) { + if (!tail_checked) + { + LOG_DEBUG(log, "Observed extra data in tablet snapshot {} beyond {}, cf {}", Redact::keyToDebugString(key.data(), key.size()), r.second.key.toDebugString(), getDebugCfType()); + tail_checked = true; + } return false; } } @@ -55,6 +60,7 @@ MonoSSTReader::MonoSSTReader(const TiFlashRaftProxyHelper * proxy_helper_, SSTVi , inner(proxy_helper->sst_reader_interfaces.fn_get_sst_reader(view, proxy_helper->proxy_ptr)) , type(view.type) , range(range_) + , tail_checked(false) { log = &Poco::Logger::get("MonoSSTReader"); kind = proxy_helper->sst_reader_interfaces.fn_kind(inner, view.type); @@ -62,7 +68,7 @@ MonoSSTReader::MonoSSTReader(const TiFlashRaftProxyHelper * proxy_helper_, SSTVi { auto && r = range->comparableKeys(); auto start = r.first.key.toString(); - LOG_DEBUG(log, "Seek cf {} to {}", static_cast::type>(type), Redact::keyToDebugString(start.data(), start.size())); + LOG_DEBUG(log, "Seek cf {} to {}", getDebugCfType(), Redact::keyToDebugString(start.data(), start.size())); if (!start.empty()) { proxy_helper->sst_reader_interfaces.fn_seek(inner, view.type, EngineIteratorSeekType::Key, BaseBuffView{start.data(), start.size()}); diff --git a/dbms/src/Storages/Transaction/SSTReader.h b/dbms/src/Storages/Transaction/SSTReader.h index f643989f9f3..95577d9562c 100644 --- a/dbms/src/Storages/Transaction/SSTReader.h +++ b/dbms/src/Storages/Transaction/SSTReader.h @@ -47,12 +47,19 @@ class MonoSSTReader : public SSTReader MonoSSTReader(const TiFlashRaftProxyHelper * proxy_helper_, SSTView view, RegionRangeFilter range_); ~MonoSSTReader() override; +private: + auto getDebugCfType() const + { + return static_cast::type>(type); + } + private: const TiFlashRaftProxyHelper * proxy_helper; SSTReaderPtr inner; ColumnFamilyType type; RegionRangeFilter range; SSTFormatKind kind; + mutable bool tail_checked; Poco::Logger * log; }; diff --git a/dbms/src/Storages/Transaction/tests/gtest_new_kvstore.cpp b/dbms/src/Storages/Transaction/tests/gtest_new_kvstore.cpp index 5e7bc1899ef..8be96b326ed 100644 --- a/dbms/src/Storages/Transaction/tests/gtest_new_kvstore.cpp +++ b/dbms/src/Storages/Transaction/tests/gtest_new_kvstore.cpp @@ -507,7 +507,39 @@ try CATCH -TEST_F(RegionKVStoreTest, KVStoreSnapshotV2) +TEST_F(RegionKVStoreTest, KVStoreSnapshotV2Extra) +try +{ + auto ctx = TiFlashTestEnv::getGlobalContext(); + ASSERT_NE(proxy_helper->sst_reader_interfaces.fn_key, nullptr); + UInt64 region_id = 2; + TableID table_id; + { + std::string start_str = "7480000000000000FF795F720000000000FA"; + std::string end_str = "7480000000000000FF795F720380000000FF0000004003800000FF0000017FCC000000FC"; + auto start = Redact::hexStringToKey(start_str.data(), start_str.size()); + auto end = Redact::hexStringToKey(end_str.data(), end_str.size()); + + initStorages(); + KVStore & kvs = getKVS(); + table_id = proxy_instance->bootstrapTable(ctx, kvs, ctx.getTMTContext()); + proxy_instance->bootstrapWithRegion(kvs, ctx.getTMTContext(), region_id, std::make_pair(start, end)); + auto kvr1 = kvs.getRegion(region_id); + auto r1 = proxy_instance->getRegion(region_id); + } + KVStore & kvs = getKVS(); + { + std::string k = "7480000000000000FF795F720380000000FF0000026303800000FF0000017801000000FCF9DE534E2797FB83"; + MockRaftStoreProxy::Cf write_cf{region_id, table_id, ColumnFamilyType::Write}; + write_cf.insert_raw(Redact::hexStringToKey(k.data(), k.size()), "v1"); + write_cf.finish_file(SSTFormatKind::KIND_TABLET); + write_cf.freeze(); + validate(kvs, proxy_instance, region_id, write_cf, ColumnFamilyType::Write, 1, 0); + } +} +CATCH + +TEST_F(RegionKVStoreTest, KVStoreSnapshotV2Basic) try { auto ctx = TiFlashTestEnv::getGlobalContext();