[MDEV-14605] ON UPDATE CURRENT_TIMESTAMP fields by multi-table UPDATE are not logged with binlog_row_image=MINIMAL Created: 2017-12-07  Updated: 2021-02-06  Resolved: 2019-01-24

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1.26
Fix Version/s: 10.1.38

Type: Bug Priority: Critical
Reporter: Geoff Montee (Inactive) Assignee: Andrei Elkin
Resolution: Fixed Votes: 0
Labels: binlog, timestamp, update

Issue Links:
Duplicate
is duplicated by MDEV-12162 binlog_row_image minimal Not Working Closed
Relates
relates to MDEV-15602 server occasionally does not update t... Closed

 Description   

When binlog_row_image=MINIMAL is configured and an "ON UPDATE CURRENT_TIMESTAMP" field is automatically changed due to an update to the row, that change should be logged to the binlog with all of the other changes to the row, but that does not always happen.

One case where this happens is when using the multi-table syntax for UPDATE. For example, run the following test:

CREATE TABLE `tab1` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `is_deleted` bit(1) DEFAULT b'0',
  `last_updated` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `ref_id` bigint(20) unsigned NOT NULL,
  PRIMARY KEY (`id`),
  KEY `last_updated_KEY` (`last_updated`)
);
 
CREATE TABLE `tab2` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `short_desc` varchar(50) NOT NULL,
  PRIMARY KEY (`id`)
);
 
INSERT INTO tab2 (id, short_desc) VALUES (1, 'test');
INSERT INTO tab1 (id, is_deleted, ref_id) VALUES (1, b'0', 1);
UPDATE tab1 t1
INNER JOIN tab2 t2 ON t1.ref_id = t2.id
SET t1.is_deleted = TRUE
WHERE t1.id = 1;

When the following is configured:

binlog_format=ROW
binlog_row_image = MINIMAL

Then the updated timestamp will be missing from the resulting binlog event created by the UPDATE statement:

# at 3829
#171207 13:45:43 server id 1  end_log_pos 3867  GTID 1-1-55 trans
/*!100001 SET @@session.gtid_seq_no=55*//*!*/;
BEGIN
/*!*/;
# at 3867
#171207 13:45:43 server id 1  end_log_pos 3915  Table_map: `db1`.`tab1` mapped to number 29
# at 3915
#171207 13:45:43 server id 1  end_log_pos 3965  Update_rows: table id 29 flags: STMT_END_F
 
BINLOG '
V4wpWhMBAAAAMAAAAEsPAAAAAB0AAAAAAAEAA2RiMQAEdGFiMQAECBARCAMBAAAC
V4wpWhgBAAAAMgAAAH0PAAAAAB0AAAAAAAEABAsC+AEAAAAAAAAAAAEAAAAAAAAA/gE=
'/*!*/;
### UPDATE `db1`.`tab1`
### WHERE
###   @1=1
###   @2=b'0'
###   @4=1
### SET
###   @2=b'1'
# at 3965
#171207 13:45:43 server id 1  end_log_pos 3992  Xid = 10
COMMIT/*!*/;

If binlog_row_image=MINIMAL is not set, then the updated value is in the binlog event:

# at 622
#171207 14:17:58 server id 1  end_log_pos 660   GTID 1-1-58 trans
/*!100001 SET @@session.gtid_seq_no=58*//*!*/;
BEGIN
/*!*/;
# at 660
#171207 14:17:58 server id 1  end_log_pos 708   Table_map: `db1`.`tab1` mapped to number 25
# at 708
#171207 14:17:58 server id 1  end_log_pos 782   Update_rows: table id 25 flags: STMT_END_F
 
BINLOG '
5pMpWhMBAAAAMAAAAMQCAAAAABkAAAAAAAEAA2RiMQAEdGFiMQAECBARCAMBAAAC
5pMpWhgBAAAASgAAAA4DAAAAABkAAAAAAAEABP//8AEAAAAAAAAAAFopk+UBAAAAAAAAAPABAAAA
AAAAAAFaKZPmAQAAAAAAAAA=
'/*!*/;
### UPDATE `db1`.`tab1`
### WHERE
###   @1=1
###   @2=b'0'
###   @3=1512674277
###   @4=1
### SET
###   @1=1
###   @2=b'1'
###   @3=1512674278
###   @4=1
# at 782
#171207 14:17:58 server id 1  end_log_pos 809   Xid = 13
COMMIT/*!*/;



 Comments   
Comment by Elena Stepanova [ 2017-12-10 ]

Reproducible with 10.1, although 10.2 seems to work all right.

Comment by Andrei Elkin [ 2019-01-21 ]

7d1cb6f1ea9 is pushed to bb-10.1-andrei. Could you please review it?

Thanks.

Andrei

Comment by Andrei Elkin [ 2019-01-24 ]

Pushed f9ac7032cbc.

Comment by Karl Klepper [ 2021-02-06 ]

I just happened to stumble upon this bug with 10.1.26-MariaDB because a cron job kept updating the same records indefinitely.

I could reproduce this via http, whereas the very same sql expression succeeded in adminer.

After I found out, the easiest way for me to proceed was to augment my query with

, tmstmp = NOW() /* was not updated automatically for no apparent reason in ... triggered by ... */

Generated at Thu Feb 08 08:14:52 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.