故障分析 | 手动 rm 掉 binlog 导致主从报错

1. 故障描述

2. 故障分析

2.1. 先登录从库查看报错信息

发现从库的 io 线程断了，并报错：Got fatal error 1236 from master when reading data from binary log: 'Could not open log file' ，从字面意思不难理解，无法从主库获取到 binlog 日志，GTID 停止在 828415 ，检查从库 error 日志报错如下：

根据从库报错信息，下一步我们去主库查看主库的 binlog 信息和 error 日志，看主库 binlog 是否有丢失的情况。

2.2. 查看主库 binlog 信息，以及 error 日志

登录主库检查 binlog 日志列表以及 index 索引文件，发现主库的 binlog 是连续的没有问题，但在查看 mysql-bin.index 文件的时候发现有记录两个 mysql-bin.000006 ，但是实际只有一个 mysql-bin.000006 文件，先记着这个奇怪的现象。

再去看一眼主库的 error 日志，内容如下，和从库 error 日志都指向同一个 binlog 。

通过解析 mysql-bin.000005 可以看到最后一个事务 gtid 为：'c582a82e-b985-11ec-adf5-02000aba3e89:828415' 为上面从库停止 gtid 的位置。

继续解析 mysql-bin.000006 查看其第一个事务的 gtid 为：'c582a82e-b985-11ec-adf5-02000aba3e89:855706' 。

3. 故障复现

3.1. 复现 index 索引文件记录相同 binlog 文件名

第一步登录主库所在的机器，在复制状态正常下，把主库正在用的 binlog 日志 rm 手动删除。

第二步进入主库执行 flush logs 刷新日志，这时 binlog 会重新生成刚刚删除的 binlog 文件，此时观察主库的 binlog 日志是连续的，index 索引文件里面出现了两个刚刚 rm 手动删除的 binlog 日志信息，即 index 文件记录着有两个相同文件，与客户场景一致。

3.2. 复现客户场景 Got fatal error 1236 from master when reading data from binary log: 'Could not open log file'

首先需要主从有一定的延迟，如下从库获取到主库 binlog.000006 。

此时将主库正在用的 binlog.000007 手动 rm 掉，这时虽然 binlog.000007 已经被删除，但仍在后台被主库占用，新的 binlog.000007 这时也还没有刷新生成，但 index 里面是有记录 binlog.000007 的。

这时当从库读取完 binlog.000006 并继续获取 binlog 索引文件里记录的 binlog.000007 时，由于此文件已经被删除且主库没有生成新的 binlog.000007 ，从而复制报错。

主从复制故障后，主库这时其实还在使用着已经删除的 binlog 文件，直到触发 flush logs  ，这时 mysql-bin.index 就会出现 3.1 场景。至此客户复制故障场景已完全复现出来。

3.3 其他场景

在主从没有延迟或者延迟较低的情况下，从库已经读取到主库正在用的 binlog.yyy 。这时将主库正在用的 binlog.yyy 删除，由于被删除的 binlog.yyy 仍在后台被占用着，所以在从库可以看到复制状态还是正常的。直到主库 binlog 文件在重新刷新（flush log 、binlog 文件写满等）生成新的 binlog.yyy 后，从库的 gtid 这时就不再更新，从库很快报错 1236 。

4. 建议

通过上面的测试可以发现人为 rm 掉正在用的 binlog 基本都会导致主从报错或主从不一致，而一旦出现这种情况除了重做从库外一般是没有其他比较好的方法，这样是不利于数据库维护，所以建议：

1. 避免对 binlog 文件做压缩删除等直接操作，可以通过调整参数修改 binlog 清理策略。

2. 需要手工删除 binlog 时，可以进入 MySQL 通过 purge 命令去删除。