DTS 同步 MySQL 到 Kafka 后下游新增字段全是默认值(0)的排查

一句话结论:下游表新增的列在库里全是默认值 0,第一反应都会怀疑 DTS / Kafka 这条 CDC 链路把新字段漏了。但逐层验证后发现 CDC 链路从头到尾都正常——列在、真实值也在;真凶是最末端那个自研 Kafka 采集器的老代码没把新列写进 SQLite。本文记录这条"先自证清白、再顺藤摸瓜"的排查,以及几招能一锤定音的实证手段:消费 Kafka 原始消息、git log -S 定位字段引入时间、查消费组已提交位点解释"为什么历史数据不会自愈"。

环境与链路

源库 MySQL(只读实例)
  └─DTS(增量同步, MySQL → Kafka)
      └─Kafka 自建实例  topic=binlog  格式=canal_json  压缩=lz4  12 分区
          └─自研采集器 cdc_collector.py(confluent-kafka 消费)
              └─本地 SQLite(下游监控库, 表 biz_events)
  • 源表:biz_task(任务表),前一晚加了两个新列 new_url、new_flag。
  • 下游表:biz_events,采集器消费 binlog 后落地,供监控大盘统计成功率/失败率用。
  • 现象:new_flag 这列在下游 SQLite 里整列全是 0,而它本该有 0/1 两种值(1=被风控拦截)。

文中所有 库名、表名、字段名、IP、实例 ID、主机名、地域、桶名均为占位,替换成你自己的即可。

先把结论用一张动图摆出来:新列从源库一路流到 Kafka 全都正常(绿色点亮),唯独最末端的采集器没把它写进 SQLite(红色断点)。

CDC 链路数据流向:绿到 Kafka 都正常,红在采集器断点

一、现象:下游统计里风控字段恒为 0

下游同事按 state(生成状态)和 new_flag(是否风控)分组统计,发现风控这列没有一个非 0:

SELECT state, new_flag, COUNT(*)
FROM biz_events
GROUP BY state, new_flag;
-- 1|0|1
-- 2|0|451      ← state=2(失败)451 条, new_flag 全是 0
-- 3|0|3252

state=2 是失败,理论上有相当一部分是被风控拦下来的,new_flag 应该是 1。整列全 0,只有两种可能:要么源头就没数据,要么链路某处把这列丢了。这条链路最长、最像"黑箱"的就是 DTS→Kafka 这段 CDC,所有人的第一怀疑都落在它身上。

但"怀疑"不能当结论。排查的第一原则是先确认现象的边界:从最上游往下,一段段证明它是否正常,而不是一上来就去改 DTS。

二、先确认源库真有这列、且有真实值

源库是只读实例,直接查表结构和最近一次结构变更时间:

SELECT ORDINAL_POSITION, COLUMN_NAME, COLUMN_TYPE, COLUMN_COMMENT
FROM information_schema.COLUMNS
WHERE TABLE_SCHEMA='<db>' AND TABLE_NAME='biz_task'
ORDER BY ORDINAL_POSITION;
-- ...
-- 16  new_url   varchar(128)  新增URL列
-- 17  new_flag  tinyint       是否风控

SELECT CREATE_TIME, UPDATE_TIME
FROM information_schema.TABLES
WHERE TABLE_SCHEMA='<db>' AND TABLE_NAME='biz_task';
-- CREATE_TIME = 2026-06-07 22:32:23   ← 注意:一张老表的 CREATE_TIME 是"昨晚"

两个关键事实:

  1. 新列 new_url(#16)、new_flag(#17) 都在表末尾——典型的"后期 ALTER ADD COLUMN 追加"特征。
  2. 一张早就存在的表,CREATE_TIME 却是昨晚 22:32。InnoDB 在 ALTER TABLE ... ADD COLUMN 走 COPY 算法重建、或在线 DDL 工具(gh-ost / pt-osc)换表时,CREATE_TIME 会刷新成重建时刻。也就是说结构变更发生在昨晚 22:32,而 DTS 任务那时早已在跑。

到这里,"DTS 拿的是旧 schema、没认到新列"的假设看起来非常合理。但合理 ≠ 事实,得去 Kafka 里看实际流过的消息。

三、进 Kafka 看 binlog topic 里到底有没有这列

DTS 写出的是 canal_json 格式,所有库表混在一个 binlog topic 里、按主键分 12 个分区、用 lz4 压缩。要验证就得起一个独立消费组(只读、绝不提交生产组的位点)去捞 biz_task 的消息。

几个坑先说在前面:

  • lz4 必装:topic 是 lz4 压缩,Python 客户端少了 lz4 库会直接抛 UnsupportedCodecError: Libraries for lz4 compression codec not found。
  • 单 topic 混所有表:必须按消息里的 table 字段过滤,否则会被高频表(日志表)刷屏。
  • 12 分区散落:同一张表的消息散在所有分区,得遍历全部分区。

只读消费脚本骨架(group_id=None + enable_auto_commit=False,纯只读、不影响任何生产消费组):

from kafka import KafkaConsumer, TopicPartition
import json
brokers = ['<broker-1>:9092', '<broker-2>:9092', '<broker-3>:9092']
c = KafkaConsumer(bootstrap_servers=brokers, group_id=None,
                  enable_auto_commit=False, consumer_timeout_ms=10000)
tps = [TopicPartition('binlog', p) for p in c.partitions_for_topic('binlog')]
c.assign(tps)
end = c.end_offsets(tps)
for tp in tps:                       # 从队尾往前回看一段
    c.seek(tp, max(0, end[tp] - 20000))
for m in c:
    d = json.loads(m.value)
    if d.get('table') != 'biz_task':
        continue
    row = d['data'][0]
    # 检查新列是否存在、值是什么

扫了约 24 万条消息、捞到 435 条 biz_task,结果一目了然:

biz_task data 435 | ddl 0
field presence over 435 data msgs: {'new_url': 435, 'new_flag': 435}
mysqlType has new_url: True | new_flag: True

两个新列在 435/435 条消息里全都在,不只 data 里有,canal_json 的 mysqlType 元信息里也有。这说明 DTS 已经认到了新表结构。一条完整的 UPDATE 消息长这样(脱敏后):

{
  "database": "<db>", "table": "biz_task", "type": "UPDATE",
  "es": 1780905236000, "isDdl": false, "pkNames": ["id"],
  "data": [{
     "id": "...", "state": "3", "...": "...",
     "new_url": "<oss-url-key>",
     "new_flag": "0"
  }],
  "old": [{ "state": "1", "new_url": "", "new_flag": "0" }],
  "mysqlType": { "...": "...", "new_url": "varchar", "new_flag": "tinyint" }
}

这条 old → data 正好拍到 state 从 1(生成中)变 3(成功)、new_url 从空被填上真实 URL的瞬间——DTS 连"后期才填上的真实值"都一条不落地带过来了。

光看一条还不够,再统计"非默认值"的占比,确认真实值确实在流动:

扫 55.2 万条 | biz_task 1012 条(291 INSERT + 721 UPDATE)
new_url 非空: 297/1012
new_flag 非0: 119/1012
  样本 type=UPDATE id=... new_flag=1 state=2

new_flag=1 的 119 条全部是 state=2(失败)——风控命中的任务最终都落到失败态,两个字段在数据里强绑定。结论很硬:Kafka 这一层,新列和它的真实 0/1 值都正常存在。

四、第一个怀疑被推翻:DTS 其实完全正常

回头补一刀确认 DTS 任务本身的配置,排除"碰巧这段时间对、之前不对"的可能。任务 2026-02-09 创建(早于昨晚加列 4 个月),同步对象里 biz_task 配的是"整表所有列(含未来新增列)",并且 DDL 转发是开的。再加上前面 Kafka 实测的 435/435 带列、119 条真实 new_flag=1,DTS→Kafka 这段被彻底洗清嫌疑。

教训一:别让"合理的假设"替代"实际的观测"。 "表昨晚重建 + DTS 早就在跑"是一个非常能自圆其说的故事,但消费一下原始消息就证明它是错的。CDC 链路是不是漏字段,消费端看一眼实际消息最快、最准。

既然 Kafka 里有,那问题只能在 Kafka 之后——也就是把 binlog 消费进 SQLite 的那个自研采集器。

五、把战场移到下游采集器

下游监控机上,/data/cdc_monitor/ 是一个 Python 工程,核心是常驻消费进程 service/cdc_collector.py:用 confluent-kafka 订阅 binlog,解析 canal_json,按表分流写进 SQLite 的 biz_events 等表。

先看下游 SQLite 表结构——它有没有 new_flag 这列:

.schema biz_events
-- CREATE TABLE biz_events (
--   id INTEGER PRIMARY KEY, type ..., state ..., ...,
--   new_flag INTEGER NOT NULL DEFAULT 0   ← 列在! 且默认 0
-- );

列是有的(否则前面那条 GROUP BY new_flag 早就报错了),只是全 0。那问题就缩小到:采集器把消息解析后写 SQLite 时,到底有没有把 new_flag 取出来赋值。

六、读代码:采集器"现在"看起来是对的

完整读 cdc_collector.py(619 行),关键三处:

# 1) 要写进 biz 表的字段列表 —— 含 new_flag
BIZ_FIELDS = [
    "id", "type", "user_id", "state", "new_flag",
    "created_at", "updated_at",          # 字段名已脱敏, 仅示意
]

# 2) UPSERT 语句 —— 列与占位符都带了 new_flag, 且顺序与上面的字段列表完全对齐
SQLITE_BIZ_UPSERT = """
INSERT OR REPLACE INTO biz_events
    (id, type, user_id, state, new_flag, created_at, updated_at)
VALUES (?, ?, ?, ?, ?, ?, ?)
"""

# 3) 从 canal_json 的 data 记录里按字段列表顺序取值, new_flag 走数值分支 int(...)
def _extract_row(self, record, target):
    fields = self._fields_for_target(target)   # biz → BIZ_FIELDS
    return tuple(int(record.get(f, 0) or 0) for f in fields)   # 简化示意

代码逻辑是对的:字段列表含 new_flag、UPSERT 含、解析时也会从消息里取。那为什么库里还是全 0?

注意一个细节:这个文件的修改时间是今天。代码"现在"是对的,不代表"一直"是对的。下一步就该去翻它的历史。

七、git pickaxe:这列是今天才加进代码的

git log -S <字符串>(俗称 pickaxe)能精确找出"哪个提交改变了某个字符串的出现次数"——用它定位 new_flag 何时第一次进入这个文件:

git -C /data/cdc_monitor log -S new_flag \
    --date=format:'%Y-%m-%d %H:%M' --pretty='%h | %ad | %s' \
    -- service/cdc_collector.py
# f4b9e26 | 2026-06-08 17:14 | 补充 new_flag 字段

只返回一个提交,今天 17:14。再看这个提交里 new_flag 相关的增减行:

cid=$(git -C /data/cdc_monitor log -S new_flag --pretty=%H \
      -- service/cdc_collector.py | tail -1)
git -C /data/cdc_monitor show $cid -- service/cdc_collector.py \
  | grep -nE '^[+-].*new_flag'
# +    "new_flag",                          ← 字段列表新增
# +    new_flag INTEGER NOT NULL DEFAULT 0, ← 建表新增
# +     ..., new_flag, ...)    ← UPSERT 新增
# +            "new_flag",                  ← 自动补列逻辑新增

全是 + 新增行,没有任何修改/删除。这就把"老代码导致"从推断变成了提交级铁证:今天 17:14 这个提交之前,cdc_collector.py 里根本没有 new_flag 这个字符串,字段列表和 UPSERT 里都没有这列。老代码写入时,这列只能取建表默认值 0。

再看进程启动时间与提交时间的关系:

ps -eo pid,lstart,cmd | grep cdc_collector
# ... Mon Jun 8 17:36:27 2026 ... run/cdc_collector.py

进程 17:36 启动(在 17:14 提交之后),也就是说当前进程跑的已经是新代码。可库里历史行依然全 0——这就引出最后一个、也是最反直觉的问题:为什么换了新代码、重启了进程,那些历史风控行还是不会变成 1?

八、为什么历史数据不会"自愈":消费组位点

很多人下意识以为"重启 = 重新消费一遍 = 历史数据会被新代码修正"。错。看采集器的消费配置:

"group.id":            "cdc_monitor_group",
"auto.offset.reset":   "latest",
"enable.auto.commit":  True,     # 边读边自动提交位点

enable.auto.commit=True 意味着消费者边读边提交位点;重启后从已提交位点之后继续,而不是从头重放。那批 new_flag=1 的消息发生在重启之前,当时正在跑的老代码已经把它们消费掉并提交了位点——重启新代码时,这些消息早已在位点后面,不会再被投递。

只读查一下消费组当前已提交位点,和队尾对比(enable_auto_commit=False,纯查询、不动真实组):

c = KafkaConsumer(bootstrap_servers=brokers, group_id='cdc_monitor_group',
                  enable_auto_commit=False)
tps = [TopicPartition('binlog', p) for p in c.partitions_for_topic('binlog')]
end = c.end_offsets(tps)
for tp in tps:
    print(tp.partition, c.committed(tp), end[tp], end[tp] - c.committed(tp))
# p0  117395678 | 117395685 | lag 7
# p9  117503173 | 117503182 | lag 9
# ...  TOTAL LAG: 97

各分区 lag 只有个位数——已提交位点贴着队尾。而之前实测那批风控消息的位点(如 p0 的 11736xxxx、p9 的 11746xxxx)全都小于当前已提交位点,即它们早被消费并提交、落在位点后面。

于是历史风控行被"三重锁死":

  1. 位点已越过:老代码消费过且提交了,重启不回放;
  2. auto.offset.reset=latest:就算位点丢了也是从最新开始,更不会回到过去;
  3. 终态不再更新:这些任务是 state=2 失败终态,源库不会再 UPDATE,Kafka 不会再有同 id 的新消息,INSERT OR REPLACE 也就永远不会被重新触发。

所以历史全 0 不会自愈,只能主动回填(回放消费组位点 / 从源库刷)或随保留期自然老化。

教训二:Kafka 消费组重启是"接着读",不是"从头放"。 改了消费端逻辑,只对之后到达的消息生效;已经消费过的历史数据要单独回填,别指望重启自动修正。

九、收尾实证:从 1 到 58

代码对、进程是新的,但还差最后一步——真有一条 风控事件经新代码端到端落库成 1 吗? 修复后恰好一段时间没有风控失败事件,验证只能等。盯着库,等到了第一条:

SELECT id, state, new_flag, datetime(updated_at,'unixepoch')
FROM biz_events WHERE state=2 ORDER BY updated_at DESC LIMIT 3;
-- 143107345612802 | 2 | 1 | 2026-06-08 11:15:19   ← 修复后第一条, 正确写成 1
-- 143090371526657 | 2 | 0 | 2026-06-08 09:07:17   ← 修复前的历史行, 仍是 0

源库风控失败 → DTS → Kafka → 新代码采集器 → SQLite,new_flag=1 一路正确落库。再过约半天回看,new_flag=1 已从 1 涨到 58 条,且能正确区分"风控失败(1)"与"其他原因失败(0)";那批修复前的 0 值历史行也随保留期陆续老化掉了。至此链路完全闭环。

下面这张图把整条链路的逐层结论钉在一起——源库→DTS→Kafka 每一段都带着新列(绿),根因只在最末端采集器老代码漏写(红):

全链路逐层定位图:DTS/Kafka 均正常带列,采集器老代码漏写致下游全 0

复盘:这次排查为什么没跑偏

  • 先自证清白,再顺藤摸瓜:面对最长、最像黑箱的 CDC 链路,没有一上来改 DTS,而是从源库→Kafka→下游一段段证明,把范围一步步缩小到最末端。
  • 观测压倒假设:"表昨晚重建、DTS 漏 schema"是个能自圆其说的故事,但消费一眼原始消息就推翻了它。排查里最危险的就是"听起来很对"的假设。
  • 用对工具一锤定音:git log -S 把"老代码导致"从推断变成提交级证据;查消费组已提交位点把"历史为什么不自愈"解释得明明白白。
  • 结论分级、留到实证:在等到 11:15 那条真实事件之前,"新代码能写 1"只是"代码看着对",不算实锤;等到 1→58 的真实数据才算闭环。

快速参考

只读消费 Kafka 验证某表某字段(不碰生产消费组)

KafkaConsumer(bootstrap_servers=[...], group_id=None,      # 匿名组, 不提交位点
              enable_auto_commit=False, consumer_timeout_ms=10000)
# lz4/snappy 压缩的 topic 记得 pip install lz4 / python-snappy
# 单 topic 混多表 → 必须按消息里的 table 字段过滤
# 多分区 → assign 全部分区; 按时间定位用 offsets_for_times({tp: 毫秒时间戳})

定位某字段/字符串何时进代码(pickaxe)

git log -S '<字符串>' --date=format:'%Y-%m-%d %H:%M' --pretty='%h|%ad|%s' -- <file>
git show <commit> -- <file> | grep -nE '^[+-].*<字符串>'   # 看增减行

只读查消费组已提交位点与 lag

c = KafkaConsumer(bootstrap_servers=[...], group_id='<组>', enable_auto_commit=False)
end = c.end_offsets(tps)
for tp in tps: print(tp.partition, c.committed(tp), end[tp], end[tp]-c.committed(tp))

几条铁律

  • 下游某列"全是默认值",先消费原始消息确认 CDC 链路有没有带这列,别先改同步任务。
  • canal_json 里 data 是新值、old 是 UPDATE 变化前的值、mysqlType 是列的类型表——三者都能用来判断"列在不在"。
  • Kafka 消费端改逻辑只对之后的消息生效;历史数据要单独回填,重启不会重放。
  • new_flag=1 与 state=2 这类强相关,既能用来交叉验证,也提醒你"字段缺失"和"值恰好都是默认"是两回事。
posted @ 2026-06-09 13:10  Hello_worlds  阅读(6)  评论(0)    收藏  举报