mysql主備切換canal出現的問題解析
通過配置VIP,在進行主備切換時,出現的報錯資訊:
1.當主備節點當前binlog檔名稱相同時,原主節點的position小於主備切換後的position,出現如下報錯:
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) 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) ]
此類報錯和max_allowed_packet相關。首先max_allowed_packet控制著主從複製過程中單個語句產生的二進位制binlog event大小,它的值必須是1024的倍數 。出現此類錯誤的常見原因:
1>.該引數在主備庫的配置大小不一致。 從主庫傳遞到備庫的binlog event大小超過了主庫或者備庫的max_allowed_packet大小。可以檢視變數值:SHOW GLOBAL VARIABLES LIKE "%max_allowed_packet%"; 看兩個庫的值是否一致。
2>.在對應個binlog檔案中找不到對應的偏移量position,可以通過mysqlbinlog命令檢視,發現沒有要報錯要找的1104(position),可以切換到存在的position位點
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 ' xfb6Xg8CAAAAdwAAAHsAAAABAAQANS43LjI4LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA 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.當mysql主備切換時,無論binlog檔名是否相同,如果原主節點position大於主備切換後主庫當前binlog的position,會報如下錯誤:
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) ]
從錯誤資訊可以看出,複製時其實position大於當前binlog檔案的大小
3.mysql主備切換時,原主庫binlog名稱序號大於切換後主庫binlog名稱序號,會報如下錯誤:
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) ]
意思是在新主庫上由於binlog名稱翻轉次數較少,binlog名稱需要比原主庫少,在新主庫上找不到對應名稱的binlog
3.使用刪除的binlog檔名稱,報如下錯誤:
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) ]
可以通過在主庫上通過"flush logs"命令重新生成資訊binlog,然後使用"show master status"查詢資訊位點,重新使用“CHANGE MASTER TO MASTER_LOG_FILE='log-bin.00000xx',MASTER_LOG_POS=xxx;
”重新同步binlog。