[MDEV-9567] mysqlbinlog fails to read binlog event which inserts timestamp with wrong number of microseconds Created: 2016-02-16  Updated: 2017-05-22  Resolved: 2016-02-18

Status: Closed
Project: MariaDB Server
Component/s: Replication, Scripts & Clients
Affects Version/s: 5.5, 10.0
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Duplicate Votes: 0
Labels: None

Issue Links:
Duplicate
duplicates MDEV-12744 Corrupted replication event was detec... Closed
is duplicated by MDEV-9560 Mariadb 10.1 Crashes when replicating... Closed
Relates
relates to MDEV-5377 Row-based replication of MariaDB temp... Closed

 Description   

In the test case below, note that f1 is TIMESTAMP(3), but the inserted value is NOW(). Apparently it's the most significant part.

--source include/have_log_bin.inc
 
--source include/have_binlog_format_row.inc
 
 
 
--let $datadir= `SELECT @@datadir`
 
 
 
DROP TABLE IF EXISTS `t1`;
 
CREATE TABLE `t1` (
 
   `f1` timestamp(3) NOT NULL DEFAULT '2016-01-01 00:00:00.000',
 
   `f2` char(13) NOT NULL,
 
   `f3` decimal(7,2) DEFAULT NULL,
 
   `f4` char(8) DEFAULT NULL,
 
   `f5` decimal(5,2) DEFAULT NULL,
 
   PRIMARY KEY (`f1`,`f2`)
 
 ) DEFAULT CHARSET=utf8;
 
INSERT INTO `t1` VALUES (NOW(),'-',0,'foo',0.0);
 
FLUSH LOGS;
 
 
 
--exec $MYSQL_BINLOG --verbose --base64-output=DECODE-ROWS $datadir/master-bin.000001
 
 
 
DROP TABLE `t1`;

Output

 
...
 
/*!100001 SET @@session.gtid_seq_no=3*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 855
 
# at 908
 
#160216 21:22:01 server id 1  end_log_pos 908   Table_map: `test`.`t1` mapped to number 82
 
#160216 21:22:01 server id 1  end_log_pos 957   Write_rows: table id 82 flags: STMT_END_F
 
### INSERT INTO `test`.`t1`
 
### SET
 
###   @1=-646528170
 
###   @2=''
 
###   @3=0
 
###   @4=''
 
###   @5=0
 
### INSERT INTO `test`.`t1`
 
### SET
 
###   @1=8417135
 
###   @2=NULL
 
###   @3=NULL
 
###   @4=''
 
###   @5=***Corrupted replication event was detected. Not printing the value***
 
# at 957
 
...

Note duplicate event, wrong values, and the corruption message.

Reproducible on 5.5.48 and 10.0.23, as well as older versions that I checked (down to 10.0.11 at least); seems to be fixed in 10.1.

Replication seems to work all right, so it's not absolutely critical, but it's very inconvenient when binlog events are important for problem investigation, so it would be good to fix it in 10.0 at least.



 Comments   
Comment by Elena Stepanova [ 2016-02-16 ]

Note: actually, the category and the affected versions that I've set contradict each other. If it's a mysqlbinlog bug, it exists in 10.1 as well, because mysqlbinlog from 10.1 also cannot read such binary log; but when the server and mysqlbinlog both are from 10.1, the problem does not happen. Please adjust the fields accordingly when you know the right values.

Comment by Elena Stepanova [ 2016-02-17 ]

Actually, I was wrong about replication. 10.0 => 10.0 works, but 10.0 => 10.1 fails.
With the same set of commands executed on master, a release 10.1 slave fails with 

              Last_SQL_Error: Could not execute Write_rows_v1 event on table test.t1; Column 'f2' cannot be null, Error_code: 1048; Unknown error, Error_code: 1105; handler error No Error!; the event's master log mysql-bin.000001, end_log_pos 1011

A debug 10.1 slave hits an assertion failure:

Stack trace from 10.1 commit d80b8442a68093106e00a9a38b7b2c593002a72c

 
2016-02-17  0:56:11 140344869202688 [ERROR] Slave SQL: Could not read field 'f5' of table 'te
 
st.t1', Gtid 0-765-3, Internal MariaDB error code: 1610
 
mysqld: /src/10.1/sql/log_event.cc:11696: virtual int Write_rows_log_event::do_exec_row(rpl_g
 
roup_info*): Assertion `0' failed.
 
160217  0:56:11 [ERROR] mysqld got signal 6 ;
 
 
 
Thread pointer: 0x0x7f98e2622cf0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x7fa4961319e0 thread_stack 0x48400
 
(my_addr_resolve failure: fork)
 
/bld/10.1/bin/mysqld(my_print_stacktrace+0x38) [0x5647769a8da7]
 
/bld/10.1/bin/mysqld(handle_fatal_signal+0x390) [0x564776356d25]
 
/lib64/libpthread.so.0(+0xf890) [0x7fa495ea8890]
 
/lib64/libc.so.6(gsignal+0x37) [0x7fa493f5f187]
 
/lib64/libc.so.6(abort+0x118) [0x7fa493f60538]
 
/lib64/libc.so.6(+0x2e126) [0x7fa493f58126]
 
/lib64/libc.so.6(+0x2e1d2) [0x7fa493f581d2]
 
/bld/10.1/bin/mysqld(Write_rows_log_event::do_exec_row(rpl_group_info*)+0x16f) [0x5647764602a9]
 
/bld/10.1/bin/mysqld(Rows_log_event::do_apply_event(rpl_group_info*)+0xe15) [0x56477645bf5b]
 
/bld/10.1/bin/mysqld(Log_event::apply_event(rpl_group_info*)+0x59) [0x564776088043]
 
/bld/10.1/bin/mysqld(apply_event_and_update_pos(Log_event*, THD*, rpl_group_info*, rpl_parallel_thread*)+0x3ca) [0x56477607de00]
 
/bld/10.1/bin/mysqld(+0x455884) [0x56477607e884]
 
/bld/10.1/bin/mysqld(handle_slave_sql+0xd54) [0x56477608197f]
 
/lib64/libpthread.so.0(+0x80a4) [0x7fa495ea10a4]
 
/lib64/libc.so.6(clone+0x6d) [0x7fa49400f04d]

So, wherever the bug is, it needs to be fixed for 10.1, I'm updating the fix version accordingly.
And now the scenario looks important enough.

Comment by Elena Stepanova [ 2016-02-18 ]

I'm closing this one as a duplicate of MDEV-9560. The problems are too interleaved, I hope everything will be fixed together. I'll continue updating MDEV-9560.

Comment by Sergei Golubchik [ 2016-02-18 ]

This is another effect of MDEV-5377.

MariaDB temporal data types with microseconds don't store enough metadata in the rbr events, so it's only possible to read these rbr event on the slave that has exactly the same table structure as the master.

Because mysqlbinlog has no tables at all, it cannot parse these rbr events correctly.

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