关于binlog:故障分析-手动-rm-掉-binlog-导致主从报错

2次阅读

共计 3044 个字符,预计需要花费 8 分钟才能阅读完成。

作者:陈伟

爱可生数据库工程师,负责 MySQL 日常保护及故障解决。

本文起源:原创投稿

* 爱可生开源社区出品,原创内容未经受权不得随便应用,转载请分割小编并注明起源。


1. 故障形容

前一段时间客户反馈复制报错 1236,依据报错提醒该报错为从库读取到了主库不存在的 binlog 日志,导致复制中断,报错截图如下,须要帮忙剖析为什么会报错 Could not open log file 起因。

2. 故障剖析

阐明:思考客户信息敏感性,以下剖析过程均在测试环境模拟,数据库版本 5.7.31,GTID 启用。

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.000006 这个 binlog 日志上,然而从下面的图中能够发现主库的 binlog 日志是有 mysql-bin.000006 这个日志的,所以咱们当初解析一下指向的 mysql-bin.000006 日志以及前一个日志 mysql-bin.000005。

通过解析 mysql-bin.000005 能够看到最初一个事务 gtid 为:’c582a82e-b985-11ec-adf5-02000aba3e89:828415’ 为下面从库进行 gtid 的地位。

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

mysql-bin.000006 第一个 GTID 事务为 855706,与 binlog.000005 文件相差了两万多个的 GTID 事务,与上一个 binlog.000005 并不间断,阐明确实存在了事务失落,当初的问题就是为什么 mysql-bin.index 文件会记录着有两个雷同 mysql-bin.000006,以及客户的故障场景是如何触发的。

3. 故障复现

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

首先依据故障剖析的后果,咱们先复现出 binlog 索引文件中 binlog 文件名反复场景。

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

第二步进入主库执行 flush logs 刷新日志,这时 binlog 会从新生成刚刚删除的 binlog 文件,此时察看主库的 binlog 日志是间断的,index 索引文件外面呈现了两个刚刚 rm 手动删除的 binlog 日志信息,即 index 文件记录着有两个雷同文件,与客户场景统一。

所以 binlog 索引文件里有两个 binlog.000006,通过下面测试能够发现,是因为当正在用的 binlog 文件被手动 rm 掉时,binlog 文件计数器是不会受到影响,当在 binlog 文件刷新后(重启、flush log、binlog 文件写满等),binlog 文件计数器会依据以后最大 binlog 文件 +1。正如下面场景第一个 binlog.000006 文件是失常记录 binlog.index 中,此时再将 binlog.000006 文件 rm 掉后,最大的为 binlog 日志为 000005,这时主库 flush logs,还会按程序在最大 binlog.00000 5 生成第二个 binlog.000006,binlog.index 中也呈现两个 binlog.000006。但主库理论曾经失落一个 binlog.000006,现有的 binlog.000006 和上一个 binlog.000005 的 gtid 也不间断,只是文件名仍间断。

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

在 3.1 的测试过程中发现客户的故障并不是肯定会呈现,还有其余景象,咱们先来复现出客户场景。

首先须要主从有肯定的提早,如下从库获取到主库 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 其余场景

在复现的过程中发现还会呈现其余不同的场景,因为篇幅较长便简略形容不再具体开展,有趣味的同学能够本人进行测试。

场景一:
主从不报错,从库丢 gtid,这种场景和下面客户复制故障的场景一样都须要有肯定的主从提早,不同点在于当从库曾经读取完 binlog.xxx 并持续获取 binlog 索引文件里记录的被 rm 删除掉 binlog.yyy 文件时,这时主库曾经触发 flush logs 生成了新的 binlog.yyy,此时从库 io 线程读取到了新的 binlog.yyy。这种状况下,从库 gtid 是不间断的,主从不统一。

场景二:
在主从没有提早或者提早较低的状况下,从库曾经读取到主库正在用的 binlog.yyy。这时将主库正在用的 binlog.yyy 删除,因为被删除的 binlog.yyy 仍在后盾被占用着,所以在从库能够看到复制状态还是失常的。直到主库 binlog 文件在从新刷新(flush log、binlog 文件写满等)生成新的 binlog.yyy 后,从库的 gtid 这时就不在更新,从库很快报错 1236。

为什么在生成新的 binlog.yyy 后就报错 1236 是因为主库 binlog 日志在从新 flush 生成新的 binlog.yyy 后,新的 binlog.yyy 事件是从 4 开始的,而此时从库曾经利用到旧 binlog.yyy 事件的地位远超 4,所以导致从库无奈从新的 binlog.yyy 读取 binlog 日志从而报错。

4. 倡议

通过下面的测试能够发现人为 rm 掉正在用的 binlog 根本都会导致主从报错或主从不统一,而一旦呈现这种状况除了重做从库外个别是没有其余比拟好的办法,这样是不利于数据库保护,所以倡议:

  1. 防止对 binlog 文件做压缩删除等间接操作,能够通过调整参数批改 binlog 清理策略.
  2. 须要手工删除 binlog 时,能够进入 MySQL 通过 purge 命令去删除。
正文完
 0