Add log when handling a snapshot with invalid data (pingcap#7581)

ref pingcap#7568
CalvinNeo · Jun 30, 2023 · 899c930 · 899c930
1 parent df781c5
commit 899c930
Show file tree

Hide file tree

Showing 4 changed files with 58 additions and 3 deletions.
diff --git 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
@@ -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,14 +60,15 @@ 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);
     if (kind == SSTFormatKind::KIND_TABLET)
     {
         auto && r = range->comparableKeys();
         auto start = r.first.key.toString();
-        LOG_DEBUG(log, "Seek cf {} to {}", static_cast<std::underlying_type<decltype(type)>::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
@@ -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<std::underlying_type<decltype(type)>::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
@@ -455,7 +455,39 @@ try
 CATCH
 
 
-TEST_F(RegionKVStoreTest, KVStoreSnapshot2)
+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();