Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.21
-
None
Description
Using encrypted binlogs it was impossible to point a Slave to the Master getting error:
2019-09-09 5:55:23 139739348764416 [ERROR] Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the first event 'mysql-binlog.016054' at 763411303, the last event read from 'mysql-binlog.nnnnn' at xxxxxxx, the last byte read from 'mysql-binlog.nnnnn at yyyyyyy. (server_errno=1236)
The error message is misleading because it's just due to pointing to a wrong position.
Using the positions reported by SHOW BINLOG EVENTS worked.
Attachments
Activity
And the reason for this is mysqlbinlog never receives the start_encryption log event. So there is no error in mysqlbinlog code.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
|
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
|
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
|
DELIMITER /*!*/;
|
# at 4
|
#190920 12:30:34 server id 1 end_log_pos 256 CRC32 0x2ca7c0fb Start: binlog v 4, server v 10.2.28-MariaDB-debug-log created 190920 12:30:34 at startup
|
ROLLBACK/*!*/;
|
BINLOG '
|
EnmEXQ8BAAAA/AAAAAABAAAAAAQAMTAuMi4yOC1NYXJpYURCLWRlYnVnLWxvZwAAAAAAAAAAAAAA
|
AAAAAAAAAAAAAAAAAAASeYRdEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
|
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
|
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
|
AAAAAAAAAAAEEwQADQgICAoKCgH7wKcs
|
'/*!*/;
|
# at 256
|
#190920 12:30:34 server id 1 end_log_pos 296 Ignorable
|
# Ignorable event type 164 (Start_encryption)
|
# at 296
|
#190920 12:30:34 server id 1 end_log_pos 325 CRC32 0x726d645b Gtid list []
|
# at 325
|
#190920 12:30:34 server id 1 end_log_pos 369 CRC32 0xd681620f Binlog checkpoint master-bin.000001
|
# at 369
|
#190920 12:30:35 server id 1 end_log_pos 411 CRC32 0x092ea4ce GTID 0-1-1 ddl
|
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
|
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
|
/*!100001 SET @@session.server_id=1*//*!*/;
|
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
|
# at 411
|
#190920 12:30:35 server id 1 end_log_pos 547 CRC32 0x7c9ee7fd Query thread_id=10 exec_time=0 error_code=0
|
use `test`/*!*/;
|
SET TIMESTAMP=1568962835/*!*/;
|
SET @@session.pseudo_thread_id=10/*!*/;
|
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;
|
SET @@session.sql_mode=1411383296/*!*/;
|
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
|
/*!\C latin1 *//*!*/;
|
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
|
SET @@session.lc_time_names=0/*!*/;
|
SET @@session.collation_database=DEFAULT/*!*/;
|
CREATE TABLE t1 (
|
id int PRIMARY KEY,
|
str varchar(50)
|
) engine=innodb
|
/*!*/;
|
# at 547
|
#190920 12:30:35 server id 1 end_log_pos 589 CRC32 0x4a287cf6 GTID 0-1-2 trans
|
/*!100001 SET @@session.gtid_seq_no=2*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 589
|
# at 647
|
#190920 12:30:35 server id 1 end_log_pos 647 CRC32 0x65a36bc5 Annotate_rows:
|
#Q> insert into t1 values (1,'row 001')
|
#190920 12:30:35 server id 1 end_log_pos 695 CRC32 0x88facad1 Table_map: `test`.`t1` mapped to number 31
|
# at 695
|
#190920 12:30:35 server id 1 end_log_pos 741 CRC32 0x5a43f9f9 Write_rows: table id 31 flags: STMT_END_F
|
|
|
BINLOG '
|
E3mEXRMBAAAAMAAAALcCAAAAAB8AAAAAAAEABHRlc3QAAnQxAAIDDwIyAALRyvqI
|
E3mEXRcBAAAALgAAAOUCAAAAAB8AAAAAAAEAAv/8AQAAAAdyb3cgMDAx+flDWg==
|
'/*!*/;
|
# at 741
|
#190920 12:30:35 server id 1 end_log_pos 772 CRC32 0x41c92b67 Xid = 22
|
COMMIT/*!*/;
|
# at 772
|
#190920 12:30:35 server id 1 end_log_pos 814 CRC32 0x2201faff GTID 0-1-3 trans
|
/*!100001 SET @@session.gtid_seq_no=3*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 814
|
# at 872
|
#190920 12:30:35 server id 1 end_log_pos 872 CRC32 0xd8ffac91 Annotate_rows:
|
#Q> insert into t1 values (2,'row 002')
|
#190920 12:30:35 server id 1 end_log_pos 920 CRC32 0xec9ee907 Table_map: `test`.`t1` mapped to number 31
|
# at 920
|
#190920 12:30:35 server id 1 end_log_pos 966 CRC32 0xc689f089 Write_rows: table id 31 flags: STMT_END_F
|
|
|
BINLOG '
|
E3mEXRMBAAAAMAAAAJgDAAAAAB8AAAAAAAEABHRlc3QAAnQxAAIDDwIyAAIH6Z7s
|
E3mEXRcBAAAALgAAAMYDAAAAAB8AAAAAAAEAAv/8AgAAAAdyb3cgMDAyifCJxg==
|
'/*!*/;
|
# at 966
|
#190920 12:30:35 server id 1 end_log_pos 997 CRC32 0x1fc2aa44 Xid = 23
|
COMMIT/*!*/;
|
# at 997
|
#190920 12:30:35 server id 1 end_log_pos 1039 CRC32 0x4c829811 GTID 0-1-4 trans
|
/*!100001 SET @@session.gtid_seq_no=4*//*!*/;
|
BEGIN
|
/*!*/;
|
# at 1039
|
# at 1097
|
#190920 12:30:35 server id 1 end_log_pos 1097 CRC32 0xe550990f Annotate_rows:
|
#Q> insert into t1 values (3,'row 003')
|
#190920 12:30:35 server id 1 end_log_pos 1145 CRC32 0x41fffdc9 Table_map: `test`.`t1` mapped to number 31
|
# at 1145
|
#190920 12:30:35 server id 1 end_log_pos 1191 CRC32 0xed74849b Write_rows: table id 31 flags: STMT_END_F
|
|
|
BINLOG '
|
E3mEXRMBAAAAMAAAAHkEAAAAAB8AAAAAAAEABHRlc3QAAnQxAAIDDwIyAALJ/f9B
|
E3mEXRcBAAAALgAAAKcEAAAAAB8AAAAAAAEAAv/8AwAAAAdyb3cgMDAzm4R07Q==
|
'/*!*/;
|
# at 1191
|
#190920 12:30:35 server id 1 end_log_pos 1222 CRC32 0x0a94e3b3 Xid = 24
|
COMMIT/*!*/;
|
DELIMITER ;
|
# End of log file
|
ROLLBACK /* added by mysqlbinlog */;
|
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
|
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
|
|
Hello Sachin,
Thanks for working on this issue.
The patch looks fine to me.
So If we look at mysqlbinlog output
#190912 17:36:35 server id 10221 end_log_pos 930 CRC32 0xb5e0e6f9 Annotate_rows:#Q> insert into tab1 values (3,'row 003')#190912 17:36:35 server id 10221 end_log_pos 980 CRC32 0x53bcb3d3 Table_map: `test`.`tab1` mapped to number 19# at 940#190912 17:36:35 server id 10221 end_log_pos 1026 CRC32 0xf2ae5136 Write_rows: table id 19 flags: STMT_END_FBINLOG 'A2Z6XRPtJwAAMgAAANQDAAAAABMAAAAAAAEABHRlc3QABHRhYjEAAgMPAjIAAtOzvFM=A2Z6XRftJwAALgAAAAIEAAAAABMAAAAAAAEAAv/8AwAAAAdyb3cgMDAzNlGu8g=='/*!*/;# at 986The difference between end pos and start pos of next event is exactly 40
And if look into show binlog events output.
+--------------------+------+-------------------+-----------+-------------+------------------------------------------------+| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |+--------------------+------+-------------------+-----------+-------------+------------------------------------------------+| tossanc-bin.000001 | 4 | Format_desc | 10221 | 256 | Server ver: 10.2.21-MariaDB-log, Binlog ver: 4 || tossanc-bin.000001 | 256 | Start_encryption | 10221 | 296 | || tossanc-bin.000001 | 296 | Gtid_list | 10221 | 325 | []The size of Start_encryption events is exactly 40.
And one more thing there is no Start_encryption event in mysqlbinlog output. So it does not print this event and that is why its counter is offset by 40