[#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.

[MDEV-31761] Timestamp is written into binary log incorrectly, causes discrepancy upon binlog replaying Created: 2023-07-21 Updated: 2023-11-28
Status:	Open
Project:	MariaDB Server
Component/s:	Replication, Temporal Types
Affects Version/s:	10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s:	10.4, 10.5, 10.6, 10.11, 11.0, 11.1

[MDEV-31761] Timestamp is written into binary log incorrectly, causes discrepancy upon binlog replaying Created: 2023-07-21 Updated: 2023-11-28