[MDEV-28229] incorrect datetime value in binlog even with STRICT_TRANS_TABLES Created: 2022-04-04  Updated: 2022-04-15  Resolved: 2022-04-11

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.3.32
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Allen Lee (Inactive) Assignee: Angelique Sklavounos (Inactive)
Resolution: Won't Fix Votes: 0
Labels: None

Attachments: Text File test_case.txt     File test_data.out    

 Description   

The customer found the 2 issues with each table and binlog.

1) binlog in insert/update/delete statement has wrong datetime value

CREATE TABLE `xxx_SEND` (
 
  `SERVICE_ID` varchar(128) COLLATE utf8_unicode_ci NOT NULL,
 
  `REQUEST_ID` varchar(128) COLLATE utf8_unicode_ci NOT NULL,
 
  `MESSAGE_ID` varchar(128) COLLATE utf8_unicode_ci NOT NULL,
 
  `STATUS` int(11) NOT NULL,
 
  `INFOBANK_GROUP_ID` varchar(28) COLLATE utf8_unicode_ci DEFAULT NULL,
 
  `INFOBANK_MESSAGE_ID` varchar(35) COLLATE utf8_unicode_ci DEFAULT NULL,
 
  `RESULT_CODE` varchar(10) COLLATE utf8_unicode_ci DEFAULT NULL,
 
  `TTL` int(11) DEFAULT NULL,
 
  `MESSAGE_TYPE` int(11) DEFAULT NULL,
 
  `REPORT_CODE` varchar(10) COLLATE utf8_unicode_ci DEFAULT NULL,
 
  `COUNT` int(11) DEFAULT NULL,
 
  `CARRIER` int(11) DEFAULT NULL,
 
  `SEND_TS` datetime(6) DEFAULT NULL,
 
  `CREATE_TS` datetime(6) NOT NULL,
 
  `REPORT_TS` datetime(6) DEFAULT NULL,
 
  `FST_REGR_ID` varchar(50) COLLATE utf8_unicode_ci,
 
  `FST_REG_TS` datetime(6) NOT NULL COMMENT,
 
  `FNL_MDFR_ID` varchar(50) COLLATE utf8_unicode_ci,
 
  `FNL_MDFY_TS` datetime(6) NOT NULL COMMENT,
 
  PRIMARY KEY (`SERVICE_ID`,`REQUEST_ID`,`MESSAGE_ID`),
 
  UNIQUE KEY `xxx_SEND_UX1` (`MESSAGE_ID`),
 
  KEY `xxx_SEND_IX1` (`INFOBANK_GROUP_ID`,`INFOBANK_MESSAGE_ID`),
 
  KEY `xxx_SEND_IX2` (`STATUS`),
 
  KEY `xxx_SEND_IX3` (`CREATE_TS`),
 
  KEY `xxx_SEND_IX4` (`CARRIER`,`INFOBANK_MESSAGE_ID`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;
 
 
 
# at 4042
 
#220331  5:00:54 server id 5888  end_log_pos 4084 CRC32 0xb5ce065c 	GTID 0-5888-544682745 trans
 
/*!100001 SET @@session.gtid_seq_no=544682745*//*!*/;
 
START TRANSACTION
 
/*!*/;
 
# at 4084
 
#220331  5:00:54 server id 5888  end_log_pos 4185 CRC32 0xeb683dbe 	Table_map: `NINDB`.`xxx_SEND` mapped to number 2366
 
# at 4185
 
#220331  5:00:54 server id 5888  end_log_pos 4389 CRC32 0xff989ecd 	Write_rows: table id 2366 flags: STMT_END_F
 
 
 
BINLOG '
 
hjVFYhMAFwAAZQAAAFkQAAAAAD4JAAAAAAEABU5JTkRCABJOSU1fVElORk9CQU5LX1NFTkQAEw8P
 
DwMPDw8DAw8DAwwMEg8MDwwTgAGAAYABVABpAB4AHgAGlgCWAPBfAL49aOs=
 
hjVFYhcAFwAAzAAAACURAAAAAD4JAAAAAAEAE/////BX+A8Aa25veC10ZWFtcy10ZXN0IAAyMDIy
 
MDMzMTA1MDA1NDI4MjIyNTI3MDAwMDAwNTU4MSUAMjAyMjAzMzEwNTAwNTQyODIyMjUyNzAwMDAw
 
MDU1ODEwMDAwMAAAAAAQJwAAAQI8AhZg5BgVbWVzc2FnZS1tYW5hZ2VyLTIyNTI3AQI8AhZg5BgV
 
bWVzc2FnZS1tYW5hZ2VyLTIyNTI3AQI8AhZg5BjNnpj/
 
'/*!*/;
 
### INSERT INTO `xxx_SEND`
 
### SET
 
###   @1='xxxxxxxxxx'
 
###   @2='20220331050054282225270000005581'
 
###   @3='2022033105005428222527000000558100000'
 
###   @4=0
 
###   @5=NULL
 
###   @6=NULL
 
###   @7=NULL
 
###   @8=NULL
 
###   @9=NULL
 
###   @10=NULL
 
###   @11=NULL
 
###   @12=10000
 
###   @13=NULL
 
###   @14='179366419-92-43 33:41:45'
 
###   @15=NULL
 
###   @16='message-manager-22527'
 
###   @17='179366419-92-43 33:41:45'
 
###   @18='message-manager-22527'
 
###   @19='179366419-92-43 33:41:45'
 
# Number of rows: 1
 
 
 
# at 7176
 
#220331  5:00:55 server id 5888  end_log_pos 7218 CRC32 0x28d1600c 	GTID 0-5888-544682750 trans
 
/*!100001 SET @@session.gtid_seq_no=544682750*//*!*/;
 
START TRANSACTION
 
/*!*/;
 
# at 7218
 
#220331  5:00:55 server id 5888  end_log_pos 7319 CRC32 0xe132389f 	Table_map: `xxx_SEND` mapped to number 2366
 
# at 7319
 
#220331  5:00:55 server id 5888  end_log_pos 7695 CRC32 0x31bcb5f5 	Update_rows: table id 2366 flags: STMT_END_F
 
 
 
BINLOG '
 
hzVFYhMAFwAAZQAAAJccAAAAAD4JAAAAAAEABU5JTkRCABJOSU1fVElORk9CQU5LX1NFTkQAEw8P
 
DwMPDw8DAw8DAwwMEg8MDwwTgAGAAYABVABpAB4AHgAGlgCWAPBfAJ84MuE=
 
hzVFYhgAFwAAeAEAAA8eAAAAAD4JAAAAAAEAE/////////BX+A8Aa25veC10ZWFtcy10ZXN0IAAy
 
MDIyMDMzMTA1MDA1NDI4MjIyNTI3MDAwMDAwNTU4MSUAMjAyMjAzMzEwNTAwNTQyODIyMjUyNzAw
 
MDAwMDU1ODEwMDAwMAAAAAAQJwAAAQI8AhZg5BgVbWVzc2FnZS1tYW5hZ2VyLTIyNTI3AQI8AhZg
 
5BgVbWVzc2FnZS1tYW5hZ2VyLTIyNTI3AQI8AhZg5BjwV/gPAGtub3gtdGVhbXMtdGVzdCAAMjAy
 
MjAzMzEwNTAwNTQyODIyMjUyNzAwMDAwMDU1ODElADIwMjIwMzMxMDUwMDU0MjgyMjI1MjcwMDAw
 
MDA1NTgxMDAwMDABAAAAECcAAAECPAIWYOQYFW1lc3NhZ2UtbWFuYWdlci0yMjUyNwECPAIWYOQY
 
FW1lc3NhZ2UtbWFuYWdlci0yMjUyNgECPAIWaj6g9bW8MQ==
 
'/*!*/;
 
### UPDATE `xxx_SEND`
 
### WHERE
 
###   @1='xxxxxxxxxx'
 
###   @2='20220331050054282225270000005581'
 
###   @3='2022033105005428222527000000558100000'
 
###   @4=0
 
###   @5=NULL
 
###   @6=NULL
 
###   @7=NULL
 
###   @8=NULL
 
###   @9=NULL
 
###   @10=NULL
 
###   @11=NULL
 
###   @12=10000
 
###   @13=NULL
 
###   @14='179366419-92-43 33:41:45'
 
###   @15=NULL
 
###   @16='message-manager-22527'
 
###   @17='179366419-92-43 33:41:45'
 
###   @18='message-manager-22527'
 
###   @19='179366419-92-43 33:41:45'
 
### SET
 
###   @1='xxxxxxxxxx'
 
###   @2='20220331050054282225270000005581'
 
###   @3='2022033105005428222527000000558100000'
 
###   @4=1
 
###   @5=NULL
 
###   @6=NULL
 
###   @7=NULL
 
###   @8=NULL
 
###   @9=NULL
 
###   @10=NULL
 
###   @11=NULL
 
###   @12=10000
 
###   @13=NULL
 
###   @14='179366419-92-43 33:41:45'
 
###   @15=NULL
 
###   @16='message-manager-22527'
 
###   @17='179366419-92-43 33:41:45'
 
###   @18='message-manager-22526'
 
###   @19='1154678313-73-83 84:23:05'
 
# Number of rows: 1
 
 
 
### DELETE FROM `xxx_SEND`
 
### WHERE
 
###   @1='xxxxxxxxxx'
 
###   @2='20220331050054282225270000005581'
 
###   @3='2022033105005428222527000000558100000'
 
###   @4=15
 
###   @5='20220331140055157A0267727457'
 
###   @6='20220331140055157A0267727457-0'
 
###   @7='R000'
 
###   @8=86400
 
###   @9=2
 
###   @10='1000'
 
###   @11=1
 
###   @12=10002
 
###   @13='522992390-90-66 55:59:05'
 
###   @14='179366419-92-43 33:41:45'
 
###   @15='2022-03-31 05:01:03.117000'
 
###   @16='message-manager-22527'
 
###   @17='179366419-92-43 33:41:45'
 
###   @18='message-manager-22527'
 
###   @19='1329010830-12-45 94:02:25'

2) Looking at shared binlog, this table did never get update/delete, but this is the only insert in binlog even though table's column data is correct datetime value.

 
 
16141 ### INSERT INTO `xxx_SEND_HISTORY`
 
16142 ### SET
 
...
 
16165 ### @23='1501856370-85-08 70:11:85'
 
16166 ### @24='408609760-32-99 37:76:65'
 
16167 ### @25='408609760-32-99 37:76:65'
 
16168 ### @26='1389127841-70-15 07:94:25'
 
16169 ### @27='577820227-63-50 65:70:25'
 
16170 ### @28=NULL
 
16171 ### @29=NULL
 
 
 
root@localhost:(none) 02:46:31>select *
 
-> from xxx_HISTORY
 
-> where SERVICE_ID='xxxxxxxxxx'
 
-> and REQUEST_ID='20220331050329362225260000000722'
 
-> and MESSAGE_ID='2022033105032936222526000000072200000';
 
+----------------------------+----------------------------+----------------------------+----------------------------+----------------------------+---------+---------+
 
| SEND_TS 									 | REPORT_TS 								  | COMPLETE_TS 							 | CREATE_TS 								  | EXPIRE_TS 								 | RULE_ID | FILE_ID |
 
+----------------------------+----------------------------+----------------------------+----------------------------+----------------------------+---------+---------+
 
| 2022-03-31 05:03:30.082000 | 2022-03-31 05:03:31.411000 | 2022-03-31 05:03:31.411000 | 2022-03-31 05:03:31.416000 | 2022-04-01 05:03:29.362000 | NULL 	 | NULL 	 |
 
+----------------------------+----------------------------+----------------------------+----------------------------+----------------------------+---------+---------+



 Comments   
Comment by sangwoo kim [ 2022-04-04 ]

I share test cases and samples.

Comment by Elena Stepanova [ 2022-04-08 ]

Any thought on why there are only some tables have that binlog entries?

Isn't the reason exactly as you revealed, that some tables were created with the old temporal format, while others didn't (or maybe they were force-altered later in their life time and thus rebuilt with the new format)?

So, at the end it is MDEV-20860 which is still present as described for tables created in the old temporal format; and since mysql56_temporal_format hasn't even been deprecated yet, such tables can technically continue being created.
It seems to be a cosmetic issue though, given that the original INSERT and the replayed binary log end up with correct values.

Elkin, are you planning to do anything about it, or should it be closed as "Won't fix" again?

Comment by Andrei Elkin [ 2022-04-11 ]

According to the reporter's

> after recovering the table with mysql56_temporal_format=ON and mysqldump, the issue disappeared

the issue must be about mysql56_temporal_format OFF -> ON replication which is not supported.

Generated at Thu Feb 08 09:59:05 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.