MySQL从库1236报错Client requested master to start replication from position ＞ file size

 一、 问题背景与现象

        周末一台物理机故障，导致A主库服务器重启，启动后发现主从同步失败，从库IO线程异常， 报错：

Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: ‘Client requested master to start replication from position > file size’

        解析从库报错时正在请求的主库binlog，其end_log_pos是 431150798，从库正在请求的位置当时没截到图（Read_Master_Log_Pos的值）。但从报错信息来看，从库请求的主库binlog位置 大于了 该binlog的文件大小，即超出了其最大位置。

        从监控看问题前后lag基本一直为0，监控获取的是seconds_behind_master的值，即从库应用日志的延迟。可以看出当时虽然无法接收主库新的日志，但从库旧日志已应用完，可以推断主库故障前主从同步延迟基本为0。

二、 处理方法

        根据Oracle官方文档 Doc ID 1595574.1，解决方法为重新指定从库日志接收位置，至下一个binlog的起点 pos=4。尝试根据此方式修复，发现重新指定后主从恢复成功，数据继续进行同步。

解决方法很简单，但还有些疑问：

• 为什么主库宕机会导致从库binlog位置错乱
• 直接跳到下一个binlog能否保证主从数据一致

三、 MySQL redo与binlog的写入机制

1. 两阶段提交

说明：此图以双1（后文会解释）设置为标准绘制

InnoDB Prepare阶段（上图中的②）

此时SQL已经成功执行，并生成事务ID信息及redo和undo的内存日志。此阶段InnoDB会写事务的redo log，但要注意的是，此时redo log只是记录了事务的所有操作日志，并没有记录提交（commit）日志，因此事务此时的状态为Prepare。此阶段对binlog不会有任何操作。

InnoDB commit 阶段（上图中的③~⑧）

这个阶段又分成两个步骤：

• 第一步写binlog（③~⑤，视参数值而定）
• 第二步完成事务的提交（commit），在redo log中记录此事务的commit 标签

此过程中是先写redo log再写binlog的。但需要注意的是，在第一阶段并没有记录完整的redo log（不包含事务的commit标签），而是在第二阶段记录完binlog后再写入redo log的commit 标签。

还要注意，这个过程中是以第二阶段中binlog的写入与否作为事务是否成功提交的标志，即binlog写入成功就认为事务成功提交了。

2. redo与binlog写入设置

       如上图，写入日志时分为3个阶段：

• 写入日志缓存
• 调用write()将内存中的日志数据写入OS缓存
• 调用fsync()将缓存中的数据落盘

因此这里可以有几种设置：

innodb_flush_log_at_trx_commit

       InnoDB存储引擎独有的参数，用于控制InnoDB的Redo log记录方式。该参数的取值范围为0、1、2，不同的值代表Redo log不同的刷盘的方式：

• 设置为0，每次事务提交时都只把redo log落入redo log buffer中即视为成功
• 设置为1，每次事务提交时将redo log持久化到磁盘才视为成功
• 设置为2，每次事务提交时都只把redo log写到OS cache即视为成功

        InnoDB有一个后台线程，每隔1秒，就会把redo log buffer中的日志，调用write写到文件系统的page cache，然后调用fsync持久化到磁盘。

       注意，事务执行中间过程的redo log也是直接写在redo log buffer中的，这些redo log也会被后台线程一起持久化到磁盘。也就是说，一个没有提交的事务的redo log，也是可能已经持久化到磁盘的。

sync_binlog

       MySQL各引擎均有的参数，sync_binlog控制binlog的写入方式：

• 设置为0，表示每次提交事务都只写到OS cache即视为成功

• 设置为1，表示每次提交事务都会持久化到磁盘才视为成功

• 设置为N（N>1），表示每次提交事务都写到OS cache，累积N个事务后才持久化到磁盘。对应的风险是：如果主机发生异常重启，会丢失最近N个事务的binlog日志。

3. 崩溃恢复流程

同样以双1设置为标准

• 在记录此事务的binlog之前和过程中发生crash：数据库在恢复后认为此事务并没有成功提交，则会回滚此事务的操作。与此同时，因为在binlog中也没有此事务的记录，所以从库也不会有此事务的数据修改。
• 在记录此事务的binlog之后发生crash：此时，即使是redo log中还没有记录此事务的commit 标签，数据库在恢复后也会认为此事务提交成功。

它会扫描最后一个binlog文件，并提取其中的事务ID，InnoDB会将那些状态为Prepare的事务（redo log没有记录commit 标签）的xid和Binlog中提取的xid做比较，如果在Binlog中存在，则提交该事务，否则回滚该事务。也就是说，binlog中记录的事务，在恢复时都会被认为是已提交事务，会在redo log中重新写入commit标志，并完成此事务的重做。与此同时，因为在binlog中已经有了此事务的记录，所有从库也会有此事务的数据修改。

四、 报错原因分析

       查看报错DB的设置，发现innodb_flush_log_at_trx_commit=2，sync_binlog=0，而主从同步相关的报错主要与sync_binlog设置有关。

问题来了，当sync_binlog设置为0，即由操作系统决定何时将binlog落盘，会发生什么？

例如以下场景

主库：

• 数据修改记录写入binlog cache，最新位置已到100
• binlog文件最新已落盘位置为80

从库：

• 从binlog cache读取数据修改记录写入relay log，位置已经到100,
• 后续从库读取relay log进行应用

假如此时断电，主库宕机：

• MySQL利用redo log进行崩溃恢复，同时会参照已落盘的binlog文件做对比，binlog cache中的数据丢失，因此主库binlog最新位置为80。
• 主库崩溃恢复后，会切换一个新的binlog并向其中写入数据。正常来说在进行日志切换时，前一个binlog会写入一条rotate记录，告诉从库应该取下一个日志了。但在主库宕机时，还来不及写入日志切换的记录，而在新日志切出后又不会再告知从库，导致从库依然希望获取旧binlog cache的下一个位置，例如101。

• 此时由于主库binlog已被截断，end pos变为80，而从库申请读取101号位置，于是出现报错，从库申请读取了主库binlog不存在的位置。

回到官方文档的解释：

 The root problem cause is that the MySQL Slave is trying to resume reading the binary log of the MySQL Master at a point in the binary log which does not exist.  

This can happen when the Master crashes sometime after the slave has had the opportunity to copy the most recent replication event into its Relay log before the MySQL Master can complete a recovery restart. The recovery restart on the MySQL Master can truncate the end of the Binary log to keep it in sync with the InnoDB data content.  In this case the Slave has logically moved past the end of file in the Master binary log. 

This means that the slave is now at least one replication event ahead of the state of the master. The master may have been in the middle of recording the full transaction to the log when it died, so the slave might not have had the chance to read an entire transaction when it lost contact with the master.

补充说明：为什么主库崩溃恢复后不告知从库切换了日志，或者从库重试下一个binlog

Why the slave can’t auto recover
The question you are probably asking yourself is why the master doesn’t just say to the slave that it should request the new binlog instead, or the slave just back off and try again with the next binlog sequence number.

At the time of this error the master doesn’t know why the binlog has not been closed properly. It is a new instance of the master reading the file and transferring the information to the slave. It doesn’t know if there is a disk failure, massive transaction loss, or even a rogue slave. Instead it needs to indicate that there is an error that it cannot resolve, and the slave should not try and resolve on its own. Far better to have replication stop until a human can intervene and check the problem than for it to continue only to break later on when inconsistencies between the slave and master trigger later errors.

五、 解决方法解析

回到开头，为什么解决方法是直接跳到下一个binlog，能否保证主从数据一致？

1. 为什么解决方法是直接跳到下一个binlog

从前面的解释可以看到，从库想要获取的最新位置实际已经领先于主库，下一个需要获取的就是主库的最新位置。

2. 能否保证主从数据一致

        sync_binlog=0时不保证。它不会强制要求将事务日志立即写入磁盘，而是依赖于操作系统来处理。因此，主服务器可能会在将事务写入二进制日志之前返回成功。实际这种设置连主库数据一致性都不保证，如果binlog cache中有提交记录，也可能导致主从数据不一致，触发后续从库同步异常。

• 如果启动时，redo文件记录最新位置 > binlog记录最新位置，则主库启动时会依据redo位置进行崩溃恢复，此时binlog数据中有部分数据缺失，直接跳到下一位可能导致主从数据不一致
• 如果启动时，binlog记录最新位置 > redo文件记录的新位置，则主库启动时会依据binlog位置进行崩溃恢复，此时binlog数据中有部分数据缺失，直接跳到下一位可能导致主从数据不一致

参考：

Doc ID 1595574.1

《MySQL 45讲》

https://juejin.cn/post/7115595536639459336

MySQL中binlog和redo log的一致性问题_binlog 和 redo不同步-CSDN博客

Client requested master to start replication from impossible position | MariaDB

Misframe - Recovering MySQL replication after error 1236

数据库内核月报

MySQL 5.6 主从报错一例_start