# [FAQ] TiDB-Binlog 报警 binlog_pump_storage_error_count 的 type 为 read_value 的原因及如何避免

## Key Words

读取失败, pump 报错

## Description

观察日志, 以 2004 not found fid 报错为例, 进行过滤会出现下述内容

```shell
cat pump_20230711.log|grep -e "2004" \
-e "read value failed" \
-e "use gc ts to detect drainer checkpoint" \
-e "drainer's checkpoint is older than pump gc ts, some binlogs are purged" \
-e "send gc request to storage" \
-e "drainer request a purged binlog TS, some binlog events may be loss" \
-e "Starting GC"

[2023/07/11 18:15:33.277 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442733463703912448]
[2023/07/11 18:15:33.278 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442752338071912448] ["drainer checkpoint"=442733638451724292]
[2023/07/11 18:15:33.392 +08:00] [INFO] [server.go:592] ["send gc request to storage"] ["request gc ts"=442734407422312448]
[2023/07/11 18:15:33.393 +08:00] [INFO] [storage.go:698] ["Starting GC"] [ts=442734250135912448]
[2023/07/11 18:15:33.504 +08:00] [INFO] [vlog.go:513] ["remove file"] [path=/tidb-data/pump-8250/value/002004.vlog]
[2023/07/11 18:15:36.586 +08:00] [ERROR] [storage.go:1177] ["read value failed"] [error="get file(id: 2004) failed: not found fid: 2004 not found"] [errorVerbose="not found fid: 2004 not found\ngithub.com/pingcap/errors.NotFoundf\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:117\ngithub.com/pingcap/tidb-binlog/pump/storage.(*valueLog).getFileRLocked\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/vlog.go:201\ngithub.com/pingcap/tidb-binlog/pump/storage.(*valueLog).readValue\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/vlog.go:322\ngithub.com/pingcap/tidb-binlog/pump/storage.(*Append).PullCommitBinlog.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/storage.go:1175\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594\nget file(id: 2004) failed"]
[2023/07/11 18:15:40.637 +08:00] [ERROR] [server.go:294] ["drainer request a purged binlog TS, some binlog events may be loss"] ["gc TS"=442734407422312448] [request="{\"clusterID\":7246735281218653461,\"startFrom\":{\"offset\":442733639277215745}}"]
[2023/07/11 18:25:33.277 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 18:25:33.281 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442733977718489091]
[2023/07/11 18:35:33.277 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 18:35:33.278 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442734441058009105]
[2023/07/11 18:45:13.273 +08:00] [INFO] [storage.go:387] [DBStats] [DBStats="{\"WriteDelayCount\":0,\"WriteDelayDuration\":0,\"WritePaused\":false,\"AliveSnapshots\":0,\"AliveIterators\":1,\"IOWrite\":442004170,\"IORead\":1608181335,\"BlockCacheSize\":8384804,\"OpenedTablesCount\":2,\"LevelSizes\":[0,17254140],\"LevelTablesCounts\":[0,1],\"LevelRead\":[0,144064757],\"LevelWrite\":[98787508,40587650],\"LevelDurations\":[2544103762,3474727334]}"]
[2023/07/11 18:45:33.277 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 18:45:33.282 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442734668625215490]
[2023/07/11 18:47:01.266 +08:00] [INFO] [storage.go:489] ["Find no MVCC record for a young txn"] ["start ts"=442780200442527761] ["elapse sec"=1]
[2023/07/11 18:47:01.724 +08:00] [INFO] [storage.go:475] ["known txn is committed or rollback from tikv"] ["start ts"=442780200442527761] ["commit ts"=442780200861958150]
[2023/07/11 18:55:33.276 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 18:55:33.278 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442734691549708297]
[2023/07/11 19:05:33.276 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 19:05:33.278 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442734710345170950]
[2023/07/11 19:15:33.277 +08:00] [INFO] [server.go:544] ["use gc ts to detect drainer checkpoint"] ["gc ts"=442734407422312448]
[2023/07/11 19:15:33.278 +08:00] [ERROR] [server.go:635] ["drainer's checkpoint is older than pump gc ts, some binlogs are purged"] [drainer=26.8.1.175:8249] ["gc ts"=442753281790312448] ["drainer checkpoint"=442734731487346695]
[2023/07/11 19:15:33.393 +08:00] [INFO] [server.go:592] ["send gc request to storage"] ["request gc ts"=442735351140974592]
[2023/07/11 19:15:33.393 +08:00] [INFO] [storage.go:698] ["Starting GC"] [ts=442735193854574592]
[2023/07/11 19:15:36.752 +08:00] [ERROR] [storage.go:1177] ["read value failed"] [error="get file(id: 2034) failed: not found fid: 2034 not found"] [errorVerbose="not found fid: 2034 not found\ngithub.com/pingcap/errors.NotFoundf\n\t/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20211224045212-9687c2b0f87c/juju_adaptor.go:117\ngithub.com/pingcap/tidb-binlog/pump/storage.(*valueLog).getFileRLocked\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/vlog.go:201\ngithub.com/pingcap/tidb-binlog/pump/storage.(*valueLog).readValue\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/vlog.go:322\ngithub.com/pingcap/tidb-binlog/pump/storage.(*Append).PullCommitBinlog.func2\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb-binlog/pump/storage/storage.go:1175\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1594\nget file(id: 2034) failed"]
[2023/07/11 19:15:41.866 +08:00] [ERROR] [server.go:294] ["drainer request a purged binlog TS, some binlog events may be loss"] ["gc TS"=442735351140974592] [request="{\"clusterID\":7246735281218653461,\"startFrom\":{\"offset\":442734731985158150}}"]
......
```

## Content

1. binlog_pump_storage_error_count 用于记录 pump 从本地 levelDB 中写入或读取过程中发生的错误
2. read_value 类型的报错, 说明 pump 无法从 levelDB 中读取到想要的信息
3. 进一步分析日志, "get file(id: 2004) failed: not found fid: 2004 not found" 指明了 levelDB 无法找到文件对应的 fd
4. 关联上下文, 会发现此时

    * ```"use gc ts to detect drainer checkpoint"``` 对应的 gcTS = 442733463703912448 = 07/09 17:15:33.392
    * ```"drainer's checkpoint is older than pump gc ts, some binlogs are purged"``` 检查到 drainer checkpoint = 442733638451724292 = 07/09 17:26:40.002
    * ```"send gc request to storage"``` 表示 pump 每 1 小時执行 1 次 gc, 把 gcTS 前推 2 天前 = 442734407422312448 = 07/09 18:15:33.392
    * ```"Starting GC"``` 计算出新的 gcTS, 逻辑为 gcTS - 10 分钟, 表示把 442734250135912448 = 07/09 18:05:33.392 前的 vlog 全刪除
    * ```"read value failed"``` 及 ```"drainer request a purged binlog TS, some binlog events may be loss"``` 表 Drainer 需要读取 442733639277215745 = 07/09 17:26:43.151 的 binlog

5. 综上, 因为 07/09 17:26:43.151 < 07/09 18:05:33.392, 说明该部分 binlog 已经被 gc 掉了, 本次的根因是 Drainer 处理得太慢, 导致要拉取的 binlog 已被GC掉, Pump 要读已被 GC 的 vlog, 导致读取失败并产生 read value failed 错误
6. 建议在 drainer 消费 binlog 比较慢的条件下, 可尝试调大 pump gc 时间以保存更多 binlog, 防止数据丢失

## Affected Versions

ALL