MySQL主从：如何处理“Got Fatal Error 1236”或 MY-013114 错误（percona译文）

错误的 GTID

如今，典型的复制设置使用 GTID 模式，完整的错误消息可能如下所示：

mysql > show replica status\G
*************************** 1. row ***************************Replica_IO_Running: NoReplica_SQL_Running: YesLast_IO_Errno: 13114
Last_IO_Error: Got fatal error 1236 from source when reading data from 
binary log: 'Cannot replicate because the 
source purged required binary logs. Replicate the missing transactions from elsewhere, or 
provision a new replica from backup. Consider increasing the source's binary 
log expiration period. The GTID set sent by the replica is '00022738-1111-1111-1111-111111111111:1-370', and the missing transactions are '00022739-2222-2222-2222-222222222222
:1-2''

所以，我们有额外的信息 – errno 13114，但它并没有增加太多：

MySQL
$ perror 13114
MySQL error code MY-013114 (ER_SERVER_SOURCE_FATAL_ERROR_READING_BINLOG)
: Got fatal error %d from source when reading data from binary log: '%-.512s'

但是，有关错误原因的更多详细信息。该消息解释说，源不再具有所需的二进制日志，并且 GTID 详细信息提供了更精确的见解：“缺少的事务是’00022739-2222-2222-2222-22222222222222222222222222222’。

进一步挖掘，我们可以看到源在 gtid_executed 中有两个 GTID 集，而副本只有一个：
— 来源

mysql > select @@global.gtid_executed,@@global.gtid_purged\G
*************************** 1. row ***************************
@@global.gtid_executed: 00022738-1111-1111-1111-111111111111:1-370,
00022739-2222-2222-2222-222222222222:1-2@@global.gtid_purged: 00022738-1111-1111-1111-111111111111:1-357,
00022739-2222-2222-2222-222222222222:1-2
1 row in set (0.00 sec)

— 副本

MySQL
mysql > select @@global.gtid_executed,@@global.gtid_purged\G
*************************** 1. row ***************************
@@global.gtid_executed: 00022738-1111-1111-1111-111111111111:1-370@@global.gtid_purged: 
1 row in set (0.00 sec)

此外，此额外集将标记为已清除。因此，无法将其提供给副本。我们称之为错误交易。

随着二进制日志的清除，我们无法调查这两个额外的事务是关于什么的，除非源实例二进制日志被备份并且我们可以在历史记录中找到它们。

假设没有办法检查这些是关于什么的。在这种情况下，恢复复制的快速解决方案是插入具有相同 GTID 的空事务，然后检查实例是否不一致（即使用 pt-table-checksum）。为了实现这一点，在 replica 上，我们可以这样做：

mysql > set gtid_next='00022739-2222-2222-2222-222222222222:1';
Query OK, 0 rows affected (0.00 sec)mysql > begin; commit;
Query OK, 0 rows affected (0.00 sec)Query OK, 0 rows affected (0.01 sec)mysql > set gtid_next='00022739-2222-2222-2222-222222222222:2';
Query OK, 0 rows affected (0.00 sec)mysql > begin; commit;
Query OK, 0 rows affected (0.00 sec)Query OK, 0 rows affected (0.01 sec)mysql > set gtid_next=automatic;
Query OK, 0 rows affected (0.00 sec)mysql > select @@global.gtid_executed,@@global.gtid_purged\G
*************************** 1. row ***************************
@@global.gtid_executed: 00022738-1111-1111-1111-111111111111:1-370,
00022739-2222-2222-2222-222222222222:1-2@@global.gtid_purged: 
1 row in set (0.00 sec)mysql > start replica;
Query OK, 0 rows affected (0.00 sec)mysql > show replica status\G
*************************** 1. row ***************************
...Replica_IO_Running: YesReplica_SQL_Running: Yes

这种情况的一个典型原因是，首先在副本上引入错误的事务，然后在某个时间，相同的副本被提升为新的源。

如果您让所有副本都以只读模式运行，为什么会发生这种情况？嗯，这是我的测试副本的情况：

mysql > select @@super_read_only,@@read_only;
+-------------------+-------------+
| @@super_read_only | @@read_only |
+-------------------+-------------+
|                 1 |           1 |
+-------------------+-------------+
1 row in set (0.00 sec)mysql > flush hosts;
Query OK, 0 rows affected, 1 warning (0.00 sec)mysql > show binlog events in 'mysql-bin.000002';
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| Log_name         | Pos | Event_type     | Server_id | End_log_pos | Info                                                              |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
| mysql-bin.000002 |   4 | Format_desc    |     22739 |         126 | Server ver: 8.0.37, Binlog ver: 4                                 |
| mysql-bin.000002 | 126 | Previous_gtids |     22739 |         197 | 00022738-1111-1111-1111-111111111111:1-357                        |
| mysql-bin.000002 | 197 | Gtid           |     22739 |         274 | SET @@SESSION.GTID_NEXT= '00022739-2222-2222-2222-222222222222:1' |
| mysql-bin.000002 | 274 | Query          |     22739 |         351 | flush hosts                                                       |
| mysql-bin.000002 | 351 | Gtid           |     22739 |         428 | SET @@SESSION.GTID_NEXT= '00022739-2222-2222-2222-222222222222:2' |
| mysql-bin.000002 | 428 | Query          |     22739 |         505 | flush hosts                                                       |
+------------------+-----+----------------+-----------+-------------+-------------------------------------------------------------------+
6 rows in set (0.00 sec)

即使开启了 super_read_only，也可以使用本地服务器的 UUID 添加二进制日志事件。因此，当稍后此 binlog 轮换并且实例被提升时，其他副本将无法同步这些事件！此问题在几年前就已报告，至今仍然有效https://bugs.mysql.com/bug.php?id=88720

max_allowed_packet太小了？

错误 1236 的另一种可能情况是 MySQL 报告超过允许的最大数据包大小。副本状态中的错误状态示例可能如下所示：

 Last_IO_Errno: 13114
Last_IO_Error: Got fatal error 1236 from source when reading data from binary log: 
'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on source; 
the first event '' at 4, the last event read from './mysql-bin.000002' at 7628, the lastbyte read from './mysql-bin.000002' at 7647.'

副本端对应的错误日志条目为：

MySQL
2024-06-05T14:19:57.956581Z 10 [ERROR] [MY-010557] [Repl] Error reading packet from server for channel '': log event entry exceeded max_allowed_packet; Increase max_allowed_packet on source; the first event '' at 4, the last event read from './mysql-bin.000002' at 7628, the last byte read from './mysql-bin.000002' at 7647. (server_errno=1236)
2024-06-05T14:19:57.956622Z 10 [ERROR] [MY-013114] [Repl] Replica I/O for channel '': Got fatal error 1236 from source when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on source; the first event '' at 4, the last event read from './mysql-bin.000002' at 7628, the last byte read from './mysql-bin.000002' at 7647.', Error_code: MY-013114

现在，上述提供的建议，以及在源上增加 max_allowed_packet 设置的错误，可能完全不合理。即使源已将其设置为最大可能值（即 1GB），也会打印它：

MySQL
mysql > select @@max_allowed_packet;
+----------------------+
| @@max_allowed_packet |
+----------------------+
|           1073741824 |
+----------------------+
1 row in set (0.00 sec)

在副本端，默认情况下，最大数据包大小通过 replica_max_allowed_packet （也是 1G）设置。

首先检查罪魁祸首二进制日志是否确实大于 1 GB 非常重要，因为如果不是，则错误很可能与日志损坏有关，例如，当源突然重新启动并sync_binlog<> 1 时。无论如何，如果 binlog 文件是可解析的，都应该用 mysqlbinlog 工具进行测试。当 binlog 文件没有完全写入磁盘时（由于突然断电），令人惊讶的是，错误消息可能看起来完全相同。

但是，如果二进制日志为 1 GB 或更大且未损坏，这可能是由于遇到以下错误（今天仍然有效）的结果： https://bugs.mysql.com/bug.php?id=107113 当单行足够大时 https://bugs.mysql.com/bug.php?id=55231 – 当二进制日志文件大小超过 4GB 时为避免此错误变体，应避免非常大的事务，并且 sync_binlog=1 应将损坏的风险降至最低。

缺少二进制日志文件

导致相同错误的另一个常见原因可能是这样的：

MySQL
Last_IO_Errno: 13114
Last_IO_Error: Got fatal error 1236 from source when reading data from binary log: 
'Could not find first log file name in binary log index file'

通常在非 GTID 模式下以及启用 GTID 模式但禁用自动定位功能时也会出现这种情况。因此，复制 IO 线程正在查看二进制日志文件和位置。

原因很简单 – 源在副本能够下载之前轮换了所需的二进制日志。因此，例如，在 source 上，有：

MySQL
mysql > show binary logs;
+------------------+-----------+-----------+
| Log_name         | File_size | Encrypted |
+------------------+-----------+-----------+
| mysql-bin.000005 |      1674 | No        |
+------------------+-----------+-----------+
1 row in set (0.00 sec)

但是副本需要前面的文件继续：

MySQL
mysql > show replica status\G
*************************** 1. row ***************************Replica_IO_State: Source_Host: 127.0.0.1Source_User: rsandboxSource_Port: 22738Connect_Retry: 60Source_Log_File: mysql-bin.000004Read_Source_Log_Pos: 716Relay_Log_File: mysql-relay.000004Relay_Log_Pos: 892Relay_Source_Log_File: mysql-bin.000004Replica_IO_Running: NoReplica_SQL_Running: Yes…Auto_Position: 0

应实施适当的日志轮换策略以避免此问题。通常，MySQL 管理员使用相对较短的保留设置（通过 binlog_expire_logs_seconds），因为很难预测磁盘空间使用情况，这取决于实际写入卷而不是时间。我认为，使用 Percona 的扩展和可变binlog_space_limit更好地利用 binlog 的专用磁盘空间要容易得多！

磁盘空间不足

源上的磁盘空间问题可能会导致错误的另一种变体，例如：

MySQLLast_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log:'binlog truncated in the middle of event; consider out of disk space on master; the first event '' at 4, the last event read from './mysqld-bin.000001' at 12826202, the last byte read from './mysqld-bin.000001' at 12826221.'