[MDEV-20574] Position of events reported by mysqlbinlog is wrong with encrypted binlogs, SHOW BINLOG EVENTS reports the correct one. - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.2.21
Fix Version/s: 10.2.28, 10.3.19, 10.4.9
Component/s: Replication
Labels:
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

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

config-sql.txt
0.7 kB
2019-09-12 16:15
mysqlbinlog.txt
4 kB
2019-09-12 16:15
show_binlog_events.txt
3 kB
2019-09-12 16:15

Activity

Ascending order - Click to sort in descending order

Claudio Nanni created issue - 2019-09-12 16:14

Claudio Nanni made changes - 2019-09-12 16:15

Field	Original Value	New Value
Attachment		config-sql.txt [ 48946 ]
Attachment		mysqlbinlog.txt [ 48947 ]
Attachment		show_binlog_events.txt [ 48948 ]

Geoff Montee (Inactive) made changes - 2019-09-12 16:46

Assignee

Andrei Elkin [ elkin ]

Sachin Setiya (Inactive) made changes - 2019-09-13 10:18

Assignee

Andrei Elkin [ elkin ]

Sachin Setiya [ sachin.setiya.007 ]

Sachin Setiya (Inactive) added a comment - 2019-09-14 14:13

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

Sachin Setiya (Inactive) added a comment - 2019-09-14 14:13 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

Sachin Setiya (Inactive) added a comment - 2019-09-14 14:44

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

Sachin Setiya (Inactive) added a comment - 2019-09-14 14:44 And the reason for this is mysqlbinlog never receives the start_encryption log event. So there is no error in mysqlbinlog code.

Sachin Setiya (Inactive) added a comment - 2019-09-20 07:05

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

Sachin Setiya (Inactive) added a comment - 2019-09-20 07:05 /*!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*/;

Sachin Setiya (Inactive) added a comment - 2019-09-20 09:18

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

Sachin Setiya (Inactive) added a comment - 2019-09-20 09:18 http://lists.askmonty.org/pipermail/commits/2019-September/014005.html

Sachin Setiya (Inactive) made changes - 2019-09-20 10:15

Status

Open [ 1 ]

Confirmed [ 10101 ]

Sachin Setiya (Inactive) made changes - 2019-09-20 10:15

Assignee	Sachin Setiya [ sachin.setiya.007 ]	Sujatha Sivakumar [ sujatha.sivakumar ]
Status	Confirmed [ 10101 ]	In Review [ 10002 ]

Sergei Golubchik made changes - 2019-09-23 16:37

Fix Version/s		10.2 [ 14601 ]
Fix Version/s		10.3 [ 22126 ]
Fix Version/s		10.4 [ 22408 ]

Sujatha Sivakumar (Inactive) added a comment - 2019-09-25 11:46

Hello Sachin,

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

Sujatha Sivakumar (Inactive) added a comment - 2019-09-25 11:46 Hello Sachin, Thanks for working on this issue. The patch looks fine to me.

Sujatha Sivakumar (Inactive) made changes - 2019-09-25 11:46

Status

In Review [ 10002 ]

Stalled [ 10000 ]

Sujatha Sivakumar (Inactive) made changes - 2019-09-25 11:47

Assignee

Sujatha Sivakumar [ sujatha.sivakumar ]

Sachin Setiya [ sachin.setiya.007 ]

Sachin Setiya (Inactive) made changes - 2019-10-08 09:06

Fix Version/s		10.2.28 [ 23910 ]
Fix Version/s		10.3.19 [ 23908 ]
Fix Version/s		10.4.9 [ 23906 ]
Fix Version/s	10.2 [ 14601 ]
Fix Version/s	10.3 [ 22126 ]
Fix Version/s	10.4 [ 22408 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:50

Workflow

MariaDB v3 [ 99618 ]

MariaDB v4 [ 156735 ]

Jira Automation (IT) made changes - 2024-07-04 03:32

Zendesk Related Tickets

155520

People

Assignee:: Sachin Setiya (Inactive)

Reporter:: Claudio Nanni

Votes:: 2 Vote for this issue

Watchers:: 7 Start watching this issue

Dates

Created:: 2019-09-12 16:14

Updated:: 2024-07-07 22:35

Resolved:: 2019-10-08 09:06

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Attachments

Activity

People

Dates

Git Integration