Repository: tikv/tikv (language: rust)

Issue:
server: add more information when default not found error is encounterred
## Development Task

`DataNotFound` is an error that may occur in exceptional situations, such as data loss caused by storage medium failure or data inconsistency resulting from a bug.

Currently, when this error occurs, the TiKV logs only contain the key information without additional context, like:
```
hint: near_load_data_by_write, key: 7480000000000000FF055F728000000000FF0000020000000000FAFFFFFFFFFFFFFFFB, thread_id: 132
```

Providing additional request context information would help with issue analysis and diagnosis.


Discussion / hints:

Fix patch:
diff --git a/Cargo.lock b/Cargo.lock
index b1d179ed5ac..d025033adc0 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -7916,6 +7916,7 @@ dependencies = [
  "codec",
  "collections",
  "error_code",
+ "fail",
  "farmhash",
  "kvproto",
  "log_wrappers",
diff --git a/components/error_code/src/coprocessor.rs b/components/error_code/src/coprocessor.rs
index dfa4749795f..259fd78f21a 100644
--- a/components/error_code/src/coprocessor.rs
+++ b/components/error_code/src/coprocessor.rs
@@ -18,5 +18,6 @@ define_error_codes!(
     STORAGE_ERROR => ("StorageError", "", ""),
     INVALID_CHARACTER_STRING => ("InvalidCharacterString", "", ""),
 
-    INVALID_MAX_TS_UPDATE => ("InvalidMaxTsUpdate", "", "")
+    INVALID_MAX_TS_UPDATE => ("InvalidMaxTsUpdate", "", ""),
+    DEFAULT_NOT_FOUND => ("DefaultNotFound", "", "")
 );
diff --git a/components/txn_types/Cargo.toml b/components/txn_types/Cargo.toml
index 19eb2f99b30..f87d470c205 100644
--- a/components/txn_types/Cargo.toml
+++ b/components/txn_types/Cargo.toml
@@ -11,6 +11,7 @@ byteorder = "1.2"
 codec = { workspace = true }
 collections = { workspace = true }
 error_code = { workspace = true }
+fail = "0.5"
 farmhash = "1.1.5"
 kvproto = { workspace = true }
 log_wrappers = { workspace = true }
diff --git a/components/txn_types/src/types.rs b/components/txn_types/src/types.rs
index e2cc91c0cd8..8766ccf96e9 100644
--- a/components/txn_types/src/types.rs
+++ b/components/txn_types/src/types.rs
@@ -5,6 +5,7 @@ use std::fmt::{self, Debug, Display, Formatter};
 use bitflags::bitflags;
 use byteorder::{ByteOrder, NativeEndian};
 use collections::HashMap;
+use fail::fail_point;
 use kvproto::kvrpcpb::{self, Assertion};
 use tikv_util::{
     codec,
@@ -23,6 +24,7 @@ pub const SHORT_VALUE_MAX_LEN: usize = 255;
 pub const SHORT_VALUE_PREFIX: u8 = b'v';
 
 pub fn is_short_value(value: &[u8]) -> bool {
+    fail_point!("is_short_value_always_false", |_| { false });
     value.len() <= SHORT_VALUE_MAX_LEN
 }
 
diff --git a/src/coprocessor/endpoint.rs b/src/coprocessor/endpoint.rs
index 40189b6f7b6..770df34d773 100644
--- a/src/coprocessor/endpoint.rs
+++ b/src/coprocessor/endpoint.rs
@@ -503,7 +503,15 @@ impl<E: Engine> Endpoint<E> {
                 COPR_RESP_SIZE.inc_by(resp.data.len() as u64);
                 resp
             }
-            Err(e) => make_error_response(e).into(),
+            Err(e) => {
+                if let Error::DefaultNotFound(errmsg) = &e {
+                    error!("default not found in coprocessor request processing";
+                        "err" => errmsg,
+                        "reqCtx" => ?&tracker.req_ctx,
+                    );
+                }
+                make_error_response(e).into()
+            }
         };
         resp.set_exec_details(exec_details);
         resp.set_exec_details_v2(exec_details_v2);
@@ -933,6 +941,10 @@ macro_rules! make_error_response_common {
                 err.set_message(e.to_string());
                 $resp.set_region_error(err);
             }
+            Error::DefaultNotFound(_) => {
+                $tag = "default_not_found";
+                $resp.set_other_error($e.to_string());
+            }
             Error::Other(_) => {
                 $tag = "other";
                 warn!("unexpected other error encountered processing coprocessor task";
diff --git a/src/coprocessor/error.rs b/src/coprocessor/error.rs
index 1ecb4479da3..719b4522e9c 100644
--- a/src/coprocessor/error.rs
+++ b/src/coprocessor/error.rs
@@ -33,6 +33,9 @@ pub enum Error {
     #[error("{0}")]
     InvalidMaxTsUpdate(#[from] concurrency_manager::InvalidMaxTsUpdate),
 
+    #[error("{0}")]
+    DefaultNotFound(String),
+
     #[error("{0}")]
     Other(String),
 }
@@ -91,6 +94,9 @@ impl From<MvccError> for Error {
         match err {
             MvccError(box MvccErrorInner::KeyIsLocked(info)) => Error::Locked(info),
             MvccError(box MvccErrorInner::Kv(kv_error)) => Error::from(kv_error),
+            e @ MvccError(box MvccErrorInner::DefaultNotFound { .. }) => {
+                Error::DefaultNotFound(e.to_string())
+            }
             e => Error::Other(e.to_string()),
         }
     }
@@ -141,6 +147,7 @@ impl ErrorCodeExt for Error {
             Error::MaxPendingTasksExceeded => error_code::coprocessor::MAX_PENDING_TASKS_EXCEEDED,
             Error::MemoryQuotaExceeded => error_code::coprocessor::MEMORY_QUOTA_EXCEEDED,
             Error::InvalidMaxTsUpdate(_) => error_code::coprocessor::INVALID_MAX_TS_UPDATE,
+            Error::DefaultNotFound { .. } => error_code::coprocessor::DEFAULT_NOT_FOUND,
             Error::Other(_) => error_code::UNKNOWN,
         }
     }
diff --git a/src/storage/mod.rs b/src/storage/mod.rs
index 5af39078648..77ec505c060 100644
--- a/src/storage/mod.rs
+++ b/src/storage/mod.rs
@@ -700,6 +700,17 @@ impl<E: Engine, L: LockManager, F: KvFormat> Storage<E, L, F> {
                                 r
                             })
                     });
+                    if let Err(
+                        e @ Error(box ErrorInner::Txn(TxnError(box TxnErrorInner::Mvcc(
+                            mvcc::Error(box mvcc::ErrorInner::DefaultNotFound { .. }),
+                        )))),
+                    ) = &result
+                    {
+                        error!("default not found in storage get";
+                            "err" => ?e,
+                            "RpcContext" => ?&ctx,
+                        );
+                    }
                     metrics::tls_collect_scan_details(CMD, &statistics);
                     metrics::tls_collect_read_flow(
                         ctx.get_region_id(),
@@ -1312,6 +1323,17 @@ impl<E: Engine, L: LockManager, F: KvFormat> Storage<E, L, F> {
                             });
                         (result, stats)
                     });
+                    if let Err(
+                        e @ Error(box ErrorInner::Txn(TxnError(box TxnErrorInner::Mvcc(
+                            mvcc::Error(box mvcc::ErrorInner::DefaultNotFound { .. }),
+                        )))),
+                    ) = &result
+                    {
+                        error!("default not found in storage batch_get";
+                            "err" => ?e,
+                            "RpcContext" => ?&ctx,
+                        );
+                    }
                     metrics::tls_collect_scan_details(CMD, &stats);
                     let now = Instant::now();
                     SCHED_PROCESSING_READ_HISTOGRAM_STATIC
diff --git a/src/storage/mvcc/mod.rs b/src/storage/mvcc/mod.rs
index e1d01f91562..f853d98b910 100644
--- a/src/storage/mvcc/mod.rs
+++ b/src/storage/mvcc/mod.rs
@@ -449,10 +449,12 @@ pub fn default_not_found_error(key: Vec<u8>, hint: &str) -> Error {
             hint,
         );
     } else {
+        let bt = backtrace::Backtrace::new();
         error!(
             "default value not found";
             "key" => &log_wrappers::Value::key(&key),
             "hint" => hint,
+            "bt" => ?bt,
         );
         Error::from(ErrorInner::DefaultNotFound { key })
     }
diff --git a/src/storage/mvcc/reader/point_getter.rs b/src/storage/mvcc/reader/point_getter.rs
index 474c789a31d..7026e3fe8ab 100644
--- a/src/storage/mvcc/reader/point_getter.rs
+++ b/src/storage/mvcc/reader/point_getter.rs
@@ -365,6 +365,12 @@ impl<S: Snapshot> PointGetter<S> {
         write_start_ts: TimeStamp,
         user_key: &Key,
     ) -> Result<Value> {
+        fail_point!("load_data_from_default_cf_default_not_found", |_| Err(
+            default_not_found_error(
+                user_key.clone().append_ts(write_start_ts).into_encoded(),
+                "load_data_from_default_cf",
+            )
+        ));
         self.statistics.data.get += 1;
         // TODO: We can avoid this clone.
         let value = self
diff --git a/src/storage/mvcc/reader/scanner/mod.rs b/src/storage/mvcc/reader/scanner/mod.rs
index 7f4fc664bb8..1cf80923d4a 100644
--- a/src/storage/mvcc/reader/scanner/mod.rs
+++ b/src/storage/mvcc/reader/scanner/mod.rs
@@ -365,6 +365,12 @@ pub fn near_load_data_by_write<I>(
 where
     I: Iterator,
 {
+    fail_point!("near_load_data_by_write_default_not_found", |_| Err(
+        default_not_found_error(
+            user_key.clone().append_ts(write_start_ts).into_encoded(),
+            "near_load_data_by_write",
+        )
+    ));
     let seek_key = user_key.clone().append_ts(write_start_ts);
     match statistics.load_data_hint() {
         LoadDataHint::NearSeek => default_cursor.near_seek(&seek_key, &mut statistics.data)?,


Test patch:
diff --git a/tests/failpoints/cases/test_coprocessor.rs b/tests/failpoints/cases/test_coprocessor.rs
index be9d978b23a..cbf9e14972a 100644
--- a/tests/failpoints/cases/test_coprocessor.rs
+++ b/tests/failpoints/cases/test_coprocessor.rs
@@ -5,18 +5,20 @@ use std::{sync::Arc, thread, time::Duration};
 use futures::executor::block_on;
 use grpcio::{ChannelBuilder, Environment};
 use kvproto::{
-    coprocessor::Request,
-    kvrpcpb::{Context, IsolationLevel},
+    coprocessor::{KeyRange, Request},
+    kvrpcpb::{Context, GetRequest, IsolationLevel, Mutation, Op},
     tikvpb::TikvClient,
 };
 use more_asserts::{assert_ge, assert_le};
+use pd_client::PdClient;
 use protobuf::Message;
 use raftstore::store::Bucket;
 use test_coprocessor::*;
+use test_raftstore::{must_kv_commit, must_kv_prewrite, must_new_cluster_and_kv_client};
 use test_raftstore_macro::test_case;
 use test_storage::*;
 use tidb_query_datatype::{
-    codec::{datum, Datum},
+    codec::{datum, table::encode_row_key, Datum},
     expr::EvalContext,
 };
 use tikv_util::HandyRwLock;
@@ -499,3 +501,89 @@ fn test_follower_buckets() {
     }
     fail::remove("skip_check_stale_read_safe");
 }
+
+#[test]
+fn test_default_not_found_log_info() {
+    let (mut cluster, _client, _ctx) = must_new_cluster_and_kv_client();
+    let pd_client = Arc::clone(&cluster.pd_client);
+    pd_client.disable_default_operator();
+
+    let product = ProductTable::new();
+    let row_key = encode_row_key(product.table_id(), 2);
+
+    let r1 = cluster.get_region(row_key.as_slice());
+    let region_id = r1.get_id();
+    let leader = cluster.leader_of_region(region_id).unwrap();
+    let epoch = cluster.get_region_epoch(region_id);
+    let mut ctx = Context::default();
+    ctx.set_region_id(region_id);
+    ctx.set_peer(leader.clone());
+    ctx.set_region_epoch(epoch);
+    let env = Arc::new(Environment::new(1));
+    let channel =
+        ChannelBuilder::new(env).connect(&cluster.sim.rl().get_addr(leader.get_store_id()));
+    let client = TikvClient::new(channel);
+
+    // Write record.
+    fail::cfg("is_short_value_always_false", "return()").unwrap();
+    let mut mutation = Mutation::default();
+    let value = b"v2".to_vec();
+    mutation.set_op(Op::Put);
+    mutation.set_key(row_key.clone());
+    mutation.set_value(value.clone());
+    let prewrite_ts = block_on(pd_client.get_tso()).unwrap().into_inner();
+    must_kv_prewrite(
+        &client,
+        ctx.clone(),
+        vec![mutation],
+        row_key.clone(),
+        prewrite_ts,
+    );
+    let commit_ts = block_on(pd_client.get_tso()).unwrap().into_inner();
+    must_kv_commit(
+        &client,
+        ctx.clone(),
+        vec![row_key.clone()],
+        prewrite_ts,
+        commit_ts,
+        commit_ts,
+    );
+
+    let env = Arc::new(Environment::new(1));
+    let channel =
+        ChannelBuilder::new(env).connect(&cluster.sim.rl().get_addr(leader.get_store_id()));
+    let client = TikvClient::new(channel);
+
+    let mut ctx = Context::default();
+    ctx.set_region_id(r1.get_id());
+    ctx.set_region_epoch(r1.get_region_epoch().clone());
+    ctx.set_peer(test_raftstore::new_peer(1, 1));
+
+    // Read with coprocessor request.
+    let read_ts = block_on(pd_client.get_tso()).unwrap().into_inner();
+    let mut cop_req = DagSelect::from(&product).build();
+    cop_req.set_context(ctx.clone());
+    cop_req.set_start_ts(read_ts);
+    let mut key_range = KeyRange::new();
+    let start_key = encode_row_key(product.table_id(), 1);
+    let end_key = encode_row_key(product.table_id(), 3);
+    key_range.set_start(start_key);
+    key_range.set_end(end_key);
+    cop_req.mut_ranges().clear();
+    cop_req.mut_ranges().push(key_range);
+    fail::cfg("near_load_data_by_write_default_not_found", "return()").unwrap();
+    let cop_resp = client.coprocessor(&cop_req).unwrap();
+    assert!(cop_resp.get_other_error().contains("default not found"));
+
+    // Read with get request.
+    let mut get_req = GetRequest::default();
+    get_req.set_context(ctx);
+    get_req.set_key(row_key.clone());
+    get_req.set_version(read_ts);
+    fail::cfg("load_data_from_default_cf_default_not_found", "return()").unwrap();
+    let get_resp = client.kv_get(&get_req).unwrap();
+    assert!(get_resp.get_error().get_abort().contains("DefaultNotFound"));
+    fail::remove("is_short_value_always_false");
+    fail::remove("near_load_data_by_write_default_not_found");
+    fail::remove("load_data_from_default_cf_default_not_found");
+}