[MDEV-7338] mysqlbinlog incorrect output when using timestamp(6) type - JIRA

Details

Type: Bug
Status: Open
Priority: Minor
Resolution: Unresolved
Affects Version/s: 5.5.36, 10.0
Fix Version/s: 10.0, 5.5
Component/s: Replication
Labels:
None

Description

Hi,

mysqlbinlog detects a "Corrupted Binlog" event when manipulating datetime fields with microsecond precision.

SET binlog_format = ROW;
FLUSH LOGS;
CREATE TABLE t1_timestamp (a serial, b timestamp);
CREATE TABLE t1_timestamp6 (a serial, b timestamp(6));
INSERT INTO t1_timestamp VALUES (NULL,NOW(6));
INSERT INTO t1_timestamp6 VALUES (NULL,NOW(6));
INSERT INTO t1_timestamp VALUES(NULL,NOW(6));

And we can now look in the content of the binary log:
mysqlbinlog -vvvv --base64-output=DECODE-ROWS mariadb-bin.000006

# at 832
#141216 17:07:06 server id 3  end_log_pos 870 	GTID 0-3-271
/*!100001 SET @@session.gtid_seq_no=271*//*!*/;
BEGIN
/*!*/;
# at 870
# at 925
#141216 17:07:06 server id 3  end_log_pos 925 	Table_map: `mariadb`.`t1_timestamp` mapped to number 88
#141216 17:07:06 server id 3  end_log_pos 967 	Write_rows: table id 88 flags: STMT_END_F
### INSERT INTO `mariadb`.`t1_timestamp`
### SET
###   @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=1418767626 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
# at 967
#141216 17:07:06 server id 3  end_log_pos 994 	Xid = 1465
COMMIT/*!*/;
# at 994
#141216 17:07:22 server id 3  end_log_pos 1032 	GTID 0-3-272
/*!100001 SET @@session.gtid_seq_no=272*//*!*/;
BEGIN
/*!*/;
# at 1032
# at 1088
#141216 17:07:22 server id 3  end_log_pos 1088 	Table_map: `mariadb`.`t1_timestamp6` mapped to number 89
#141216 17:07:22 server id 3  end_log_pos 1133 	Write_rows: table id 89 flags: STMT_END_F
### INSERT INTO `mariadb`.`t1_timestamp6`
### SET
###   @1=3 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=447582292 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
### INSERT INTO `mariadb`.`t1_timestamp6`
### SET
###   @1=***Corrupted replication event was detected. Not printing the value***
# at 1133
#141216 17:07:22 server id 3  end_log_pos 1160 	Xid = 1466
COMMIT/*!*/;
# at 1160
#141216 17:11:24 server id 3  end_log_pos 1198 	GTID 0-3-273
/*!100001 SET @@session.gtid_seq_no=273*//*!*/;
BEGIN
/*!*/;
# at 1198
# at 1253
#141216 17:11:24 server id 3  end_log_pos 1253 	Table_map: `mariadb`.`t1_timestamp` mapped to number 88
#141216 17:11:24 server id 3  end_log_pos 1295 	Write_rows: table id 88 flags: STMT_END_F
### INSERT INTO `mariadb`.`t1_timestamp`
### SET
###   @1=4 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2=1418767884 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
# at 1295
#141216 17:11:24 server id 3  end_log_pos 1322 	Xid = 1467
COMMIT/*!*/;
DELIMITER ;
# End of log file

Data is replicating and in sync between master/slaves.

Joffrey

Gliffy Diagrams

Attachments

Activity

Hide

Permalink

Elena Stepanova added a comment - 2014-12-18 23:20

We inherited this problem with MySQL 5.5.36 merge, particularly with this revision:

revno: 4561
revision-id: venkatesh.duggirala@oracle.com-20131217164122-15k1qf139cl7ztuk
parent: kent.boortz@oracle.com-20131214120536-569ctp2js29775o7
committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com>
branch nick: mysql-5.5
timestamp: Tue 2013-12-17 22:11:22 +0530
message:
  Bug#17632978 SLAVE CRASHES IF ROW EVENT IS CORRUPTED
  (MYSQLBINLOG -V CRASHES WITH THAT BINLOG)
  
  Problem: If slave receives a corrupted row event,
  slave server is crashing.
  
  Analysis: When slave is unpacking the row event, it is
  not validating the data before applying the event. If the
  data is corrupted for eg: the length of a field is wrong,
  it could end up reading wrong data leading to a crash.
  A similar problem happens when mysqlbinlog tool is used
  against a corrupted binlog using '-v' option. Due to -v
  option, the tool tries to print the values of all the
  fields. Corrupted field length could lead to a crash.
  
  Fix: Before unpacking the field, a verification
  will be made on the length. If it falls into the event
  range, only then it will be unpacked. Otherwise,
  "ER_SLAVE_CORRUPT_EVENT" error will be thrown.
  Incase mysqlbinlog -v case, the field value will not be
  printed and the processing of the file will be stopped.

But I'm not sure we can call it an upstream bug, since MySQL 5.5 does not have microseconds, hence it's not a problem there.

Show

Elena Stepanova added a comment - 2014-12-18 23:20 We inherited this problem with MySQL 5.5.36 merge, particularly with this revision: revno: 4561 revision-id: venkatesh.duggirala@oracle.com-20131217164122-15k1qf139cl7ztuk parent: kent.boortz@oracle.com-20131214120536-569ctp2js29775o7 committer: Venkatesh Duggirala<venkatesh.duggirala@oracle.com> branch nick: mysql-5.5 timestamp: Tue 2013-12-17 22:11:22 +0530 message: Bug#17632978 SLAVE CRASHES IF ROW EVENT IS CORRUPTED (MYSQLBINLOG -V CRASHES WITH THAT BINLOG) Problem: If slave receives a corrupted row event, slave server is crashing. Analysis: When slave is unpacking the row event, it is not validating the data before applying the event. If the data is corrupted for eg: the length of a field is wrong, it could end up reading wrong data leading to a crash. A similar problem happens when mysqlbinlog tool is used against a corrupted binlog using '-v' option. Due to -v option, the tool tries to print the values of all the fields. Corrupted field length could lead to a crash. Fix: Before unpacking the field, a verification will be made on the length. If it falls into the event range, only then it will be unpacked. Otherwise, "ER_SLAVE_CORRUPT_EVENT" error will be thrown. Incase mysqlbinlog -v case, the field value will not be printed and the processing of the file will be stopped. But I'm not sure we can call it an upstream bug, since MySQL 5.5 does not have microseconds, hence it's not a problem there.

mysqlbinlog incorrect output when using timestamp(6) type

Details

Description

Gliffy Diagrams

Attachments

Activity

People

Dates

Agile