[MDEV-7338] mysqlbinlog incorrect output when using timestamp(6) type Created: 2014-12-17  Updated: 2022-09-08

Status: Open
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 5.5.36, 10.0
Fix Version/s: 5.5

Type: Bug Priority: Minor
Reporter: Joffrey MICHAIE (Inactive) Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 0
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



 Comments   
Comment by Elena Stepanova [ 2014-12-18 ]

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.

Generated at Thu Feb 08 07:18:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.