一、pump 日志错误信息疑问

在pump 排查问题的时候（6.1.5版本），偶然发现一条错误日志， [ERROR] [server.go:635]drainer's checkpoint is older than pump gc ts, some binlogs are purged，draine=drainerip:port,gc ts=2023-07-10 06:05,drainer checkpoint=2023-07-09 11:05（为了便于表达，直接将相应的ts转为了相应的时间） 第一眼看到这条日志的时候，正如日志所描述的以为drainer 要从pump 读取的数据已经被pump给gc了，但是详细看了下这条日志的上下文及结合代码的逻辑,发现drainer 要从pump 读取的数据 其实没有被pump gc了，那为什么会显示出这样的日志呢？

二、日志初步检查

从日志来看，是在说drainer 要从pump 里面读取07-09 11:05之后的数据(下文简称drainer request ts)，但是gc ts是07-10 06:05，看起来drainer request ts 小于gc ts，drainer 要从pump获取[07-09 11:05,07-10 06:05]这个区间的数据已经被pump gc给进行purge了，但是事实真的这样嘛？我翻了下pump 上下文的日志，通过grep -in 'request gc ts' pump.log 可以看到最近一次pump的gc时间（pump 每小时gc一次)，通过最近一次pump的gc的日志记录，可以看到pump当前的最大gc ts时间（当前时间-pump配置的gc参数）为07-09 10:05 ，也就是说07-09 10:05之前的数据被pump给gc了，但是drainer request ts 是2023-07-09 11:05，并不需要读取pump 07-09 10:05之前的数据，那么日志显示的drainer's checkpoint is older than pump gc ts, some binlogs are purged.....，这条日志就打印的有问题了，并且这个日志还是ERROR 级别，本着好奇的态度去翻了下pump相关的代码

三、代码逻辑

日志里面显示关于这部分逻辑的代码在pump/server.go:635行detectDrainerCheckPoints方法里面，下面是相关代码

if drainer.MaxCommitTS < gcTS {
    log.Error("drainer's checkpoint is older than pump gc ts, some binlogs are purged",
       zap.String("drainer", drainer.NodeID),
       zap.Int64("gc ts", gcTS),
       zap.Int64("drainer checkpoint", drainer.MaxCommitTS),
    )
    // will add test when binlog have failpoint
    detectedDrainerBinlogPurged.WithLabelValues(drainer.NodeID).Inc()
}

这个代码的逻辑还是比较简单的，如果drainer.MaxCommitTS < gcTS，就会打印错误日志"drainer's checkpoint is older than pump gc ts, some binlogs are purged"....，drainer.MaxCommitTS 这个变量的值其实就是drainer 同步pump数据到哪个tso了(就是drainer savepoint里面的commitTS)，那么关键是gcTS 变量是怎么求出来的，gcTSs是该方法的传入的参数，而detectDrainerCheckPoints方法 被pump/server.go:546行被调用

gcTS := s.storage.GetGCTS()
alertGCMS := earlyAlertGC.Nanoseconds() / 1000 / 1000
alertGCTS := gcTS + int64(storage.EncodeTSO(alertGCMS))

log.Info("use gc ts to detect drainer checkpoint", zap.Int64("gc ts", gcTS))
// detect whether the binlog before drainer's checkpoint had been purged
s.detectDrainerCheckPoints(s.ctx, alertGCTS)

通过上面代码可以看到gcTS是通过alertGCTS这个参数变量传递进来的，alertGCTS的取值=gcTS +alertGCMS，gcTS的值是通过 s.storage.GetGCTS()该方法的来的，该方法返回的gcTS其实就是pump 最近一次gc的gc tso（当前时间-pump配置的gc参数，也就是说pump 已经把这个时间点以前的数据给gc了），这就是在日志里面看到的request gc ts的时间是07-09 10:05

[INFO] [server.go:592] ["send gc request to storage"] ["request gc ts"=07-09 10:05]

那么alertGCMS的值是多少呢？其实alertGCMS在代码里面写死了

earlyAlertGC                    = 20 * time.Hour
//pump/server.go:56

那也就是说在detectDrainerCheckPoints方法里面判断drainer请求的数据是否被pump给gc的时候，是和gcTS这个变量做比较，但是这个gcTS 是实际的 gcTS +20h，所以才会有上述的日志报错说drainer 请求的pump日志被purged,

了。

四、总结

代码看到这里，其实我们知道这个报错的根本的原因就找到了，但是为什么要把gcTS+20h才去做判断呢？对于这一点，笔者提出猜想，这可能是一个历史遗留问题，可能是想让提醒用户drainer 归档binlog太慢了，需要读取的pump 数据有被gc的风险，一般出现这个错误日志的时候,drainer那边归档binlog的速度其实是比较慢的，在这种情况下，才会出现这个告警，但是具体为什么这么设计可能只有开发同学才知道了，在这里我们就不做过多的研究了，但是这条日志笔者还是认为不应该是ERROR级别，并且输出信息也应该改进下，不然容易导致用户的误解。