[MDEV-20574] Position of events reported by mysqlbinlog is wrong with encrypted binlogs, SHOW BINLOG EVENTS reports the correct one. Created: 2019-09-12  Updated: 2019-10-08  Resolved: 2019-10-08

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.2.21
Fix Version/s: 10.2.28, 10.3.19, 10.4.9

Type: Bug Priority: Major
Reporter: Claudio Nanni Assignee: Sachin Setiya (Inactive)
Resolution: Fixed Votes: 2
Labels: None

Attachments: Text File config-sql.txt     Text File mysqlbinlog.txt     Text File show_binlog_events.txt    

 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.

 Comments   
Comment by Sachin Setiya (Inactive) [ 2019-09-14 ]

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_F
 
 
 
BINLOG '
 
A2Z6XRPtJwAAMgAAANQDAAAAABMAAAAAAAEABHRlc3QABHRhYjEAAgMPAjIAAtOzvFM=
 
A2Z6XRftJwAALgAAAAIEAAAAABMAAAAAAAEAAv/8AwAAAAdyb3cgMDAzNlGu8g==
 
'/*!*/;
 
# at 986

The 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

Comment by Sachin Setiya (Inactive) [ 2019-09-14 ]

And the reason for this is mysqlbinlog never receives the start_encryption log event. So there is no error in mysqlbinlog code.

Comment by Sachin Setiya (Inactive) [ 2019-09-20 ] 

/*!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*/;

Comment by Sachin Setiya (Inactive) [ 2019-09-20 ]

http://lists.askmonty.org/pipermail/commits/2019-September/014005.html

Comment by Sujatha Sivakumar (Inactive) [ 2019-09-25 ]

Hello Sachin,

Thanks for working on this issue.
The patch looks fine to me.

Generated at Thu Feb 08 09:00:31 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.