基于binlog检查数据错误
起因
某个表的 status 「莫名其妙」变成 0 了
其实可以判断出是 status 没有被赋值,通常是结构体的 status 默认是 0 才会被插入数据库。
于是问题看起来就很简单了:只要检查相关的更新操作中的 status 字段有没有被赋值即可。
但是
这个表是用户表。
- 因为历史原因,源码中的更新函数很多
- 调用更新函数的地方也很多
- 无法复现该问题,测试人员也不知道做了什么操作状态变成 0 的
所以同事关注这个问题挺久了,也没看到问题原因(当然我也没看到……)
但是恰好我在做导出 binlog 日志,判断某行数据丢失的问题,于是顺手将该问题对应的数据库、表结构一并导出,查看 status=0 的 binlog 看看情况。
coding
因为我们内部对 https://github.com/go-mysql-org/go-mysql
这个库做了很多的封装。 所以下面我们在处理 binlog 时,仅展示事件部分,其他的数据库连接之类的暂且忽略。
func (f FileOutBound) OnEvent(event types.Event) error { if event.Database != "project" { return nil } mustTableSet := map[string]bool{ "invitation": true, "org_user": true, "team_member": true, }
, err := f.f.WriteString(event.Print()) if err != nil { panic(err) } , err = f.f.Write([]byte("\r\n")) if err != nil { panic(err) } return nil }
上面的代码就是响应 binlog 的 row 日志(原始的 row 已被解析成 Event 结构体)。 为了避免日志过多过大,所以仅处理 project 这个数据库,并且仅仅关注 invitaion 等 3 张表。
这里是直接将事件输出到文件,便于我们在电脑上直接处理。
分析日志文件
数据导出后,我们找到将某行数据的 status 改成 0 的 binlog row。 通常一行 row event 数据长这个样子:
{ "action": "UPDATE", "database": "project", "old_values": "('QmPCusvS','呀呀呀','yayaya','xxxx@yeah.net',1)", "pos": { "part": "mysql-bin.001591", "offset": 515629163 }, "table": "org_user", "values": "('QmPCusvS','呀呀呀','yayaya','xxxx@yeah.net',0)" }
可以看到数据结构大概是 action 操作方式;database 数据库;old_value 、values 旧新数据;pos 表示这行数据出现在哪个 binlog 文件以及对应的 offset 偏移。
上面的 json 中我们可以看到 旧数据中 stauts 还是 1(最后一个字段),新数据中 status 变成了 0。
因为我们知道了 pos 中这行数据的位置,所以我们可以看看这个 binlog 的上下文长什么样了。
在数据库中执行:
show binlog events in 'mysql-bin.001591' FROM 515629163 limit 100;
返回结果:
mysql-bin.001591 515629163 Anonymous_Gtid 1 515629228 SET @@SESSION.GTID_NEXT= 'ANONYMOUS' mysql-bin.001591 515629228 Query 1 515629309 BEGIN mysql-bin.001591 515629309 Table_map 1 515629403 table_id: 3407638 (project.team) mysql-bin.001591 515629403 Write_rows 1 515629521 table_id: 3407638 flags: STMT_END_F mysql-bin.001591 515629521 Table_map 1 515629593 table_id: 3411634 (project.team_config) mysql-bin.001591 515629593 Write_rows 1 515629665 table_id: 3411634 flags: STMT_END_F mysql-bin.001591 515629665 Table_map 1 515629771 table_id: 3407636 (project.org_user) mysql-bin.001591 515629771 Update_rows 1 515630301 table_id: 3407636 flags: STMT_END_F mysql-bin.001591 515630301 Table_map 1 515630372 table_id: 3407637 (project.team_member) mysql-bin.001591 515630372 Write_rows 1 515630435 table_id: 3407637 flags: STMT_END_F mysql-bin.001591 515630435 Table_map 1 515630513 table_id: 3411635 (project.dashboard) mysql-bin.001591 515630513 Write_rows 1 515630610 table_id: 3411635 flags: STMT_END_F mysql-bin.001591 515630610 Table_map 1 515630695 table_id: 3411637 (project.card)
可以看到上下文中有 BEGIN 开启事务(因为这个事务比较多,下面还有很多内容已删除忽略),所以我们看到事务中有 team、team_config、org_user
等等表。
因为这种上下午内容通常只有一个地方会有,所以我们锁定了「创建团队」这个操作,并且将操作定位到 team_config 表操作和 team_member 表 到中间操作。
那么在代码中缩小了范围之后,很快就定位到问题了:
插入到 org_user 数据在读取的适合,没有取 status 状态,所以默认是 0,于是被插入到了数据库中。
完
随着代码规模的变大,有些问题没那么好检查了,那么通过 binlog 的方式,还是能帮助定位这些问题的。
整个处理过程就完事了,最开始是想通过 https://github.com/zendesk/maxwell
这个 java 库来导出 binlog,并输出成 txt 文件。
结果这个库的 filter 功能并不好用,无法满足我的筛选功能,所以索性手写。
整个查处过程还是挺好玩的,自己踩的坑并没有在文中提及。