暂无图片
暂无图片
暂无图片
暂无图片
暂无图片
首页 / 故障处理：MYSQL主主模式同步异常

故障处理：MYSQL主主模式同步异常

IT那活儿 2023-04-07
1262

点击上方“IT那活儿”公众号，关注后了解更多内容，不管IT什么活儿，干就完了！！！




故障背景



现象：

A库主机发生重启，B库同步失败。恢复B库后，A库同步也出现了异常。

环境：

  • A库  os：redhat7，DB：mysql 5.7.31
  • B库  os：redhat7，DB：mysql 5.7.31
架构：
主主模式。



B库同步失败处理



1. 检查B库同步状态

发现报错信息为Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from position > file size'。
mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: xx.xxx.159.174
Master_User: bomcsyn
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.008187
Read_Master_Log_Pos: 138485439
Relay_Log_File: bomc_ywcj_mysql01-relay-bin.016374
Relay_Log_Pos: 367
Relay_Master_Log_File: mysql-bin.008187
Slave_IO_Running: No
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 138485439
Relay_Log_Space: 633
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 1236
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'
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 174
Master_UUID: d1ee7997-e92b-11eb-b343-5254003d9e6b
Master_Info_File: data/mysqldata/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp: 230318 10:11:40
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
2. 检查sync参数
发现sync_binlog设置为2，那么A库主机发生重启确实有可能会导致os cache没有刷到磁盘上。
3. 检查error日志
报错信息与查出来的也是一致的。
2023-03-18T02:07:40.615734Z 1 [ERROR] Slave I/O for channel '': error reconnecting to master 'bomcsyn@xx.xxx.159.174:3306' - retry-time: 60 retries: 135, Error_code: 2003
2023-03-18T02:08:40.616545Z 1 [ERROR] Slave I/O for channel '': error reconnecting to master 'bomcsyn@xx.xxx.159.174:3306' - retry-time: 60 retries: 136, Error_code: 2003
2023-03-18T02:09:40.617356Z 1 [ERROR] Slave I/O for channel '': error reconnecting to master 'bomcsyn@xx.xxx.159.174:3306' - retry-time: 60 retries: 137, Error_code: 2003
2023-03-18T02:10:40.618217Z 1 [ERROR] Slave I/O for channel '': error reconnecting to master 'bomcsyn@xx.xxx.159.174:3306' - retry-time: 60 retries: 138, Error_code: 2003
2023-03-18T02:10:49.544210Z 34278496 [Note] Start binlog_dump to master_thread_id(34278496) slave_server(174), pos(mysql-bin.008378, 339282363)
2023-03-18T02:11:40.620616Z 1 [Note] Slave for channel '': connected to master 'bomcsyn@xx.xxx.159.174:3306',replication resumed in log 'mysql-bin.008187' at position 138485439
2023-03-18T02:11:40.621755Z 1 [ERROR] Error reading packet from server for channel '': Client requested master to start replication from position > file size (server_errno=1236)
2023-03-18T02:11:40.621773Z 1 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from position > file size', Error_code: 1236
2023-03-18T02:11:40.621777Z 1 [Note] Slave I/O thread exiting for channel '', read up to log 'mysql-bin.008187', position 138485439
2023-03-18T02:13:23.486432Z 34228651 [Note] Aborted connection 34228651 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.71' (Got timeout reading communication packets)
2023-03-18T02:13:23.486458Z 34261393 [Note] Aborted connection 34261393 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.71' (Got timeout reading communication packets)
2023-03-18T02:17:53.822482Z 34266564 [Note] Aborted connection 34266564 to db: 'aicompo' user: 'toptea' host: 'xx.xxx.199.67' (Got timeout reading communication packets)
2023-03-18T02:18:20.921701Z 34279201 [Note] Access denied for user 'root'@'localhost' (using password: NO)
2023-03-18T02:18:26.590465Z 34263822 [Note] Aborted connection 34263822 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.69' (Got timeout reading communication packets)
2023-03-18T02:18:59.358392Z 34266663 [Note] Aborted connection 34266663 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.65' (Got timeout reading communication packets)
2023-03-18T02:23:05.118458Z 34260224 [Note] Aborted connection 34260224 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.99.72' (Got timeout reading communication packets)
2023-03-18T02:23:38.294041Z 34279710 [Note] Access denied for user 'root'@'localhost' (using password: YES)
2023-03-18T02:24:27.038414Z 34267197 [Note] Aborted connection 34267197 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.65' (Got timeout reading communication packets)
2023-03-18T02:24:27.038462Z 34267196 [Note] Aborted connection 34267196 to db: 'aiops-app' user: 'toptea' host: '1xx.xxx.199.65' (Got timeout reading communication packets)
2023-03-18T02:26:05.342435Z 34267388 [Note] Aborted connection 34267388 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.65' (Got timeout reading communication packets)
2023-03-18T02:32:38.558457Z 34268018 [Note] Aborted connection 34268018 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.65' (Got timeout reading communication packets)
2023-03-18T02:37:22.815385Z 34278496 [Note] Aborted connection 34278496 to db: 'unconnected' user: 'bomcsyn' host: 'xx.xxx.159.174' (failed on flush_net())
2023-03-18T02:37:49.854471Z 34262820 [Note] Aborted connection 34262820 to db: 'aiops-app' user: 'toptea' host: 'xx.xxx.199.71' (Got timeout reading communication packets)
2023-03-18T02:38:29.918282Z 34281133 [Note] Start binlog_dump to master_thread_id(34281133) slave_server(174), pos(mysql-bin.008380, 216073106)
2023-03-18T02:39:23.038499Z 34268433 [Note] Aborted connection 34268433 to db: 'aicompo' user: 'toptea' host: 'xx.xxx.199.241' (Got timeout reading communication packets)
4. 在A库上对8187这个binlog进行dump，查找end pos位置
$ mysqlbinlog mysql-bin.008187 > 1.txt
查看1.txt，在文件结尾找到end_log_pos后的数字（138484267）。
BINLOG '
Mv0UZBOrAAAAUQAAALcYQQgAAOIHDAAAAAEABGdyYXAAGGlwdHBhX2RmX2Jhc2VsaW5lX2RldGFp
bAAGEg8PDwMPCQAsAVgCLAG4CzhOCUM0
Mv0UZB6rAAAAVQEAAAwaQQgAAOIHDAAAAAEAAgAG/8CZr6TuQAYA6YK16ZizIQDlvIDmiLdb5Y+3
56CB5qCh6aqMXS3ljY7ljZflrp7ljoUSAOWNjuWNl+WunuWOheW8gOaItwAAAADnAGluZGV4Ols4
OTddLOWAvDpbMjAyMy0wMy0xMSAxNDo1Nz0wLjAsMjAyMy0wMy0xNSAxNDo1Nz0wLjAsMjAyMy0w
My0xMyAxNDo1Nz0wLjAsMjAyMy0wMy0xNCAxNDo1Nz0wLjAsMjAyMy0wMy0xMiAxNDo1Nz0wLjAs
MjAyMy0wMy0xNiAxNDo1Nz0wLjAsMjAyMy0wMy0xNyAxNDo1Nz0wLjAsXSzmr5TnjodbMC42XSzk
uLTml7blubPlnYflgLw6WzAuMF0s5q+b5Yi6OltdLOacgOe7iOW5s+Wdh+WAvDpbMC4wXQEJEII=
'/*!*/;
# at 138484236
#230318 7:52:18 server id 171 end_log_pos 138484267 CRC32 0xc6a4e1c3 Xid = 21335968734
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
5. 进行修复
指定到binlog 8187，pos138484267，然后启动slave进程，同步恢复正常。
mysql> stop slave;
Query OK, 0 rows affected (0.00 sec)

mysql> change master to master_log_file='mysql-bin.008187',master_log_pos=138484267;
Query OK, 0 rows affected (0.01 sec)

mysql> start slave;
Query OK, 0 rows affected (0.00 sec)

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: xx.xxx.159.174
Master_User: bomcsyn
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.008188
Read_Master_Log_Pos: 2190802
Relay_Log_File: bomc_ywcj_mysql01-relay-bin.000003
Relay_Log_Pos: 992
Relay_Master_Log_File: mysql-bin.008188
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 2190802
Relay_Log_Space: 1377
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 174
Master_UUID: d1ee7997-e92b-11eb-b343-5254003d9e6b
Master_Info_File: data/mysqldata/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)



A库同步失败处理



1. B库同步恢复正常后，登入A库查看同步状态

提示Got fatal error 1236 from master when reading data from binary log: 'Could not find first log file name in binary log index file'。

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: xx.xxx.159.171
Master_User: bomcsyn
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.00838
Read_Master_Log_Pos: 335522704
Relay_Log_File: bomc_ywcj_mysql02-relay-bin.000001
Relay_Log_Pos: 4
Relay_Master_Log_File: mysql-bin.00838
Slave_IO_Running: No
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 335522704
Relay_Log_Space: 154
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Could not find first log file name in binary log index file'
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 171
Master_UUID: 44f8de2d-e931-11eb-80ed-525400cb2730
Master_Info_File: /data/mysqldata/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State:
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp: 230318 10:54:59
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
2. 检查相应的binlog文件和index文件以及数据库里面记录的文件名
发现文件和记录都能一一对应上，不存在问题。
3. B库主机也未发生重启，检查都未发现问题
正常来说重启复制就可以正常同步。
仔细检查后发现binlog的序号少了一位数，正确的序号是008380，而数据库中显示00838，所以导致数据库无法找到该binlog文件。
4. 手工指定为binlog 8380，pos335522704（即当前位置）
还是无法正常同步。
mysql> stop slave;
Query OK, 0 rows affected (0.00 sec)

mysql> reset slave;
Query OK, 0 rows affected (0.01 sec)

mysql> CHANGE MASTER TO MASTER_LOG_FILE='mysqld-bin.008380',MASTER_LOG_POS=335522704;
Query OK, 0 rows affected (0.04 sec)

mysql> start slave;
Query OK, 0 rows affected (0.00 sec)

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State:
Master_Host: xx.xxx.159.171
Master_User: bomcsyn
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysqld-bin.008380
Read_Master_Log_Pos: 335522704
Relay_Log_File: bomc_ywcj_mysql02-relay-bin.000001
Relay_Log_Pos: 4
Relay_Master_Log_File: mysqld-bin.008380
Slave_IO_Running: No
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 335522704
Relay_Log_Space: 154
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 1236
Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Could not find first log file name in binary log index file'
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 171
Master_UUID: 44f8de2d-e931-11eb-80ed-525400cb2730
Master_Info_File: /data/mysqldata/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp: 230318 12:54:15
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
5. 原因—误操作 
原因已找到，有人误操作，指定binlog的时候少敲个0，导致进程找不到binlog。手工在指定正确的名字也不行，尝试重建复制关系。
检查gtid是关闭的。
mysql> stop slave;
Query OK, 0 rows affected (0.00 sec)

mysql> reset slave all;
Query OK, 0 rows affected (0.02 sec)

mysql> change master to
-> master_host='xx.xxx.159.171',
-> master_port=3306,
-> master_user='bomcsyn',
-> master_password='***********',
-> master_log_file='mysql-bin.008380',
-> master_log_pos=335522704;
Query OK, 0 rows affected, 2 warnings (0.04 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)

mysql> show slave status\G;
*************************** 1. row ***************************
Slave_IO_State: Queueing master event to the relay log
Master_Host: xx.xxx.159.171
Master_User: bomcsyn
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.008380
Read_Master_Log_Pos: 708767713
Relay_Log_File: bomc_ywcj_mysql02-relay-bin.000002
Relay_Log_Pos: 9201792
Relay_Master_Log_File: mysql-bin.008380
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 344724176
Relay_Log_Space: 373245548
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 10520
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 171
Master_UUID: 44f8de2d-e931-11eb-80ed-525400cb2730
Master_Info_File: /data/mysqldata/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Reading event from the relay log
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
同步状态恢复正常。

建 议:

该库业务压力不大，建议innodb_flush_log_at_trx_commit和sync_binlog都设置为1，避免主机异常宕机导致同步失败。

END


本文作者：汤 杰(上海新炬中北团队）

本文来源：“IT那活儿”公众号

log文件mastermysql主主同步errnomysql
文章转载自IT那活儿，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

评论