Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-9567

mysqlbinlog fails to read binlog event which inserts timestamp with wrong number of microseconds

Details

    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.

      Attachments

        Issue Links

          Activity

            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.

            elenst Elena Stepanova added a comment - 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.

            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.

            elenst Elena Stepanova added a comment - 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.

            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.

            elenst Elena Stepanova added a comment - 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 .

            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.

            serg Sergei Golubchik added a comment - 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.

            People

              serg Sergei Golubchik
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

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