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

Timestamp is written into binary log incorrectly, causes discrepancy upon binlog replaying




      When the current timestamp has microseconds below 100000, it loses leading zeros when written into the binary log. So, when the binlog is replayed, statements inserting into timestamp columns end up with wrong values.

      It also causes further, more obvious, errors, for example if the mixed replication switches to row format, row events on such tables can no longer be executed, as they refer to rows which aren't in the table.

      --source include/have_binlog_format_mixed.inc
      reset master;
      create table t (a int, b timestamp(6) default current_timestamp(6) on update current_timestamp(6));
      set @@timestamp= 1689978980.012345;
      insert into t (a) values (1);
      select * from t;
      flush binary logs;
      set @@timestamp= 1689978980.567890;
      update t set a = 2 limit 1;
      flush binary logs;
      drop table t;
      --let $datadir= `select @@datadir`
      --exec $MYSQL_BINLOG $datadir/master-bin.000001 | $MYSQL test
      select * from t;
      --exec $MYSQL_BINLOG $datadir/master-bin.000002 | $MYSQL test
      # Cleanup
      drop table t;

      In the test case above, the first INSERT inserts a row with timestamp 1689978980.012345:

      10.4 30f3db3c

      a	b
      1	2023-07-22 01:36:20.012345

      However, in the binlog the query event looks like this:

      #230722  1:36:20 server id 1  end_log_pos 677 CRC32 0xac4d9e3d  Query   thread_id=5     exec_time=1476  error_code=0
      SET TIMESTAMP=1689978980.12345/*!*/;
      insert into t (a) values (1)

      So, upon binlog replaying, the inserted value is

      select * from t;
      1	2023-07-22 01:36:20.123450

      The test case also does UPDATE, to demonstrate the second point. Since it's update with limit without order by, it switches to row format. So, the row event in the log is

      #230722  1:36:20 server id 1  end_log_pos 582 CRC32 0xc781f9ec  Update_rows: table id 32 flags: STMT_END_F
      ### UPDATE `test`.`t`
      ### WHERE
      ###   @1=1
      ###   @2=1689978980.012345
      ### SET
      ###   @1=2
      ###   @2=1689978980.567890
      # Number of rows: 1

      But it cannot be executed, because there is no such value in the table, so at this point binlog replay fails with

      ERROR 1032 (HY000) at line 36: Can't find record in 't'

      2023-07-22  2:00:56 7 [ERROR] mysqld: Can't find record in 't'
      2023-07-22  2:00:56 7 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table test.t; Can't find record in 't', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 582, Internal MariaDB error code: 1032

      Replication however works, at least in this case. I can only guess that the timestamp reading logic on the slave matches the timestamp writing on the master, so it ends up interpreting the value correctly.




            Elkin Andrei Elkin
            elenst Elena Stepanova
            0 Vote for this issue
            1 Start watching this issue



              Git Integration

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