Solution to the problem of mysql master-slave switch canal

After configuring VIP, the error message that appears during active/standby switching is:

1. When the current binlog file names of the master and standby nodes are the same, the position of the original master node is smaller than the position after the master-standby switch, and the following error is reported:

2020-07-02 15:08:09,332 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:293 | Register slave RegisterSlaveCommandPacket[reportHost=192.168.3.1,reportPort=63292,reportUser=canal_repl_user,reportPasswd=111111,serverId=10236,command=21]
2020-07-02 15:08:21,227 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:321 | COM_BINLOG_DUMP with position:BinlogDumpCommandPacket[binlogPosition=1104,slaveServerId=10236,binlogFileName=mysql-bin.000002,command=18]
2020-07-02 15:08:24,979 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] LogEvent:122 | common_header_len= 19, number_of_event_types= 38
2020-07-02 15:08:24,983 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] DirectLogFetcher:163 | I/O error while reading from client socket
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the first event 'mysql-bin.000002' at 1104, the last event read from '/usr/local/mysql/logs/mysql-bin.000002' at 123, the last byte read from '/usr/local/mysql/logs/mysql-bin.000002' at 1123.
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-02 15:08:24,989 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:301 | dump address 192.168.3.100/192.168.3.100:3306 has an error, retrying. caused by 
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the first event 'mysql-bin.000002' at 1104, the last event read from '/usr/local/mysql/logs/mysql-bin.000002' at 123, the last byte read from '/usr/local/mysql/logs/mysql-bin.000002' at 1123.
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
000002' at 1123. 2020-07-02 15:08:24,994 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] LogAlarmHandler:19 | destination:1-236[java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the first event 'mysql-bin.000002' at 1104, the last event read from '/usr/local/mysql/logs/mysql-bin.000002' at 123, the last byte read from '/usr/local/mysql/logs/mysql-bin.000002' at 1123.
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
]

This type of error is related to max_allowed_packet. First, max_allowed_packet controls the size of the binary binlog event generated by a single statement during the master-slave replication process. Its value must be a multiple of 1024. Common reasons for this error:

1>. The configuration size of this parameter in the primary and standby databases is inconsistent. The size of the binlog event transferred from the primary database to the standby database exceeds the max_allowed_packet size of the primary or standby database. You can view the variable value: SHOW GLOBAL VARIABLES LIKE "%max_allowed_packet%"; to see if the values of the two libraries are consistent.

2>. If the corresponding offset position cannot be found in the corresponding binlog file, you can check it through the mysqlbinlog command. If you find that there is no 1104 (position) to be found in the error report, you can switch to the existing position site

mysqlbinlog mysql-bin.000002 --stop-position=1200

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#200630 16:24:37 server id 2 end_log_pos 123 CRC32 0x87e4bed6 Start: binlog v 4, server v 5.7.28-log created 200630 16:24:37
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
xfb6Xg8CAAAAdwAAAHsAAAABAAQANS43LjI4LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Ada+5Ic=
'/*!*/;
# at 123
#200630 16:24:37 server id 2 end_log_pos 234 CRC32 0xd95db8f4 Previous-GTIDs
# b3a0925e-b78b-11ea-9b67-000c2915fd70:51-55,
# b85582c3-14d9-11ea-a64a-000c29ab1835:40-52
# at 234
#200630 16:25:23 server id 1 end_log_pos 299 CRC32 0x0ed285db GTID last_committed=0 sequence_number=1 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'b85582c3-14d9-11ea-a64a-000c29ab1835:53'/*!*/;
# at 299
#200630 16:25:23 server id 1 end_log_pos 362 CRC32 0x34ec0ffb Query thread_id=11 exec_time=0 error_code=0
SET TIMESTAMP=1593505523/*!*/;
SET @@session.pseudo_thread_id=11/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=524288/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 362
#200630 16:25:23 server id 1 end_log_pos 427 CRC32 0x62a09b2f Table_map: `test`.`test_canal_2_hive` mapped to number 114
# at 427
#200630 16:25:23 server id 1 end_log_pos 492 CRC32 0x0f349879 Write_rows: table id 114 flags: STMT_END_F

BINLOG '
8/b6XhMBAAAAQQAAAKsBAAAAAHIAAAAAAAEABHRlc3QAEXRlc3RfY2FuYWxfMl9oaXZlAAMIDxED
UAAABi+boGI=
8/b6Xh4BAAAAQQAAAOwBAAAAAHIAAAAAAAEAAgAD//iYAAAAAAAAABB6aGFuZ3Nhbi0wMS1zMTI5
Xvr283mYNA8=
'/*!*/;
# at 492
#200630 16:25:23 server id 1 end_log_pos 523 CRC32 0x9d38dbb3 Xid = 542
COMMIT /*!*/;
# at 523
#200630 16:31:33 server id 1 end_log_pos 588 CRC32 0x7a71df00 GTID last_committed=1 sequence_number=2 rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'b85582c3-14d9-11ea-a64a-000c29ab1835:54'/*!*/;
# at 588
#200630 16:31:33 server id 1 end_log_pos 651 CRC32 0xec353d4a Query thread_id=11 exec_time=0 error_code=0
SET TIMESTAMP=1593505893/*!*/;
BEGIN
/*!*/;
# at 651
#200630 16:31:33 server id 1 end_log_pos 716 CRC32 0x0309e1d5 Table_map: `test`.`test_canal_2_hive` mapped to number 114
# at 716
#200630 16:31:33 server id 1 end_log_pos 781 CRC32 0xb7ac4767 Write_rows: table id 114 flags: STMT_END_F

BINLOG '
Zfj6XhMBAAAAQQAAAMwCAAAAAHIAAAAAAAEABHRlc3QAEXRlc3RfY2FuYWxfMl9oaXZlAAMIDxED
UAAABtXhCQM=
Zfj6Xh4BAAAAQQAAAA0DAAAAAHIAAAAAAAEAAgAD//iZAAAAAAAAABB6aGFuZ3Nhbi0wMS1zMTI5
Xvr4ZWdHrLc=
'/*!*/;
# at 781
#200630 16:31:33 server id 1 end_log_pos 812 CRC32 0xa8c3ce12 Xid = 550
COMMIT /*!*/;
# at 812
#200630 16:52:25 server id 1 end_log_pos 877 CRC32 0x8e7366ee GTID last_committed=2 sequence_number=3 rbr_only=no
SET @@SESSION.GTID_NEXT= 'b85582c3-14d9-11ea-a64a-000c29ab1835:55'/*!*/;
# at 877
#200630 16:52:25 server id 1 end_log_pos 1122 CRC32 0xb5c35333 Query thread_id=11 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1593507145/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
GRANT REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'canal_repl_user'@'%' IDENTIFIED WITH 'mysql_native_password' AS '*FD571203974BA9AFE270FE62151AE967ECA5E0AA'
/*!*/;
# at 1122
#200630 16:52:29 server id 1 end_log_pos 1187 CRC32 0x2f039a0c GTID last_committed=3 sequence_number=4 rbr_only=no
SET @@SESSION.GTID_NEXT= 'b85582c3-14d9-11ea-a64a-000c29ab1835:56'/*!*/;
# at 1187
#200630 16:52:29 server id 1 end_log_pos 1278 CRC32 0x0348011d Query thread_id=11 exec_time=0 error_code=0
SET TIMESTAMP=1593507149/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
flush privileges
/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

2. When MySQL is switched between master and slave, regardless of whether the binlog file name is the same, if the original master node position is greater than the current binlog position of the master database after the master-slave switch, the following error will be reported:

2020-07-02 14:51:16,671 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:293 | Register slave RegisterSlaveCommandPacket[reportHost=192.168.3.1,reportPort=60838,reportUser=canal_repl_user,reportPasswd=111111,serverId=10236,command=21]
2020-07-02 14:51:16,671 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:321 | COM_BINLOG_DUMP with position:BinlogDumpCommandPacket[binlogPosition=10262,slaveServerId=10236,binlogFileName=mysql-bin.000002,command=18]
2020-07-02 14:51:16,672 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] DirectLogFetcher:163 | I/O error while reading from client socket
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Client requested master to start replication from position > file size
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-02 14:51:16,673 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:301 | dump address 192.168.3.100/192.168.3.100:3306 has an error, retrying. caused by 
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Client requested master to start replication from position > file size
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-02 14:51:16,769 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] LogAlarmHandler:19 | destination:1-236[java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Client requested master to start replication from position > file size
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
]

From the error message, we can see that the position is actually larger than the size of the current binlog file during copying.

3. When MySQL is switched between master and slave, if the original master database binlog name serial number is greater than the master database binlog name serial number after the switch, the following error will be reported:

2020-07-06 11:35:07,977 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:293 | Register slave RegisterSlaveCommandPacket[reportHost=192.168.3.1,reportPort=59469,reportUser=canal_repl_user,reportPasswd=111111,serverId=10236,command=21]
2020-07-06 11:35:07,978 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:321 | COM_BINLOG_DUMP with position:BinlogDumpCommandPacket[binlogPosition=1411,slaveServerId=10236,binlogFileName=mysql-bin.000003,command=18]
2020-07-06 11:35:07,979 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] DirectLogFetcher:163 | I/O error while reading from client socket
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-06 11:35:07,980 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:301 | dump address 192.168.3.100/192.168.3.100:3306 has an error, retrying. caused by 
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-06 11:35:07,987 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] LogAlarmHandler:19 | destination:1-236[java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
]

This means that because the number of binlog name rollovers on the new master is less, the binlog name needs to be less than that of the original master, and the binlog with the corresponding name cannot be found on the new master.

3. Use the deleted binlog file name and report the following error:

2020-07-03 18:07:53,443 WARN [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:456 | prepare to find start position mysql-bin.000001:4:1593507861000
2020-07-03 18:07:53,443 WARN [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:205 | ---> find start position successfully, EntryPosition[included=false,journalName=mysql-bin.000001,position=4,serverId=<null>,gtid=<null>,timestamp=1593507861000] cost : 40ms , the next step is binlog dump
2020-07-03 18:07:53,444 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnector:101 | disConnect MysqlConnection to /192.168.3.100:3306...
2020-07-03 18:07:53,446 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnector:79 | connect MysqlConnection to /192.168.3.100:3306...
2020-07-03 18:07:53,447 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnector:182 | handshake initialization packet received, prepare the client authentication packet to send
2020-07-03 18:07:53,447 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnector:199 | client authentication packet is sent out.
2020-07-03 18:07:53,458 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:293 | Register slave RegisterSlaveCommandPacket[reportHost=192.168.3.1,reportPort=49875,reportUser=canal_repl_user,reportPasswd=111111,serverId=10236,command=21]
2020-07-03 18:07:53,459 INFO [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlConnection:321 | COM_BINLOG_DUMP with position:BinlogDumpCommandPacket[binlogPosition=4,slaveServerId=10236,binlogFileName=mysql-bin.000001,command=18]
2020-07-03 18:07:53,460 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] DirectLogFetcher:163 | I/O error while reading from client socket
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-03 18:07:53,462 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] MysqlEventParser:301 | dump address /192.168.3.100:3306 has an error, retrying. caused by 
java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
2020-07-03 18:07:53,463 ERROR [destination = 1-236 , address = /192.168.3.100:3306 , EventParser] LogAlarmHandler:19 | destination:1-236[java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file
 at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102)
 at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:169)
 at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:279)
 at java.lang.Thread.run(Thread.java:748)
]

You can regenerate the information binlog by using the "flush logs" command on the master database, then use the "show master status" command to query the information position, and re-use "CHANGE MASTER TO MASTER_LOG_FILE='log-bin.00000xx',MASTER_LOG_POS=xxx;" to resynchronize the binlog.

Summarize

This is the end of this article about solving some problems in MySQL master-slave switch canal. For more information about MySQL master-slave switch canal problems, please search 123WORDPRESS.COM's previous articles or continue to browse the following related articles. I hope everyone will support 123WORDPRESS.COM in the future!

You may also be interested in:

mysql-canal-rabbitmq installation and deployment super detailed tutorial
Detailed explanation of the binlog log analysis tool for monitoring MySQL: Canal
SpringBoot integrates Elasticsearch to implement indexing and document operations
Use elasticsearch to delete index data regularly
Use canal to monitor MySQL database to implement real-time update of elasticsearch index

<<: JS realizes picture digital clock

>>: How to fix the four sides of the table to scroll up, down, left and right