[MDEV-15602] server occasionally does not update timestamp for column (ON UPDATE CURRENT_TIMESTAMP) Created: 2018-03-19  Updated: 2019-03-27  Resolved: 2019-03-27

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Update
Affects Version/s: 10.1.28
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: chad ambrosius Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

ubuntu 14.04

Attachments: File 383_variables.out    
Issue Links:
Relates
relates to MDEV-15710 server occasionally does not not use ... Closed
relates to MDEV-6849 ON UPDATE CURRENT_TIMESTAMP doesn't a... Closed
relates to MDEV-14605 ON UPDATE CURRENT_TIMESTAMP fields by... Closed

 Description   

I have a table with a timestamp column with "ON UPDATE CURRENT_TIMESTAMP" that behaves correctly almost always. but occasionally that timestamp column is NOT modified when the row is updated.
the table definition is similar to:

CREATE TABLE `table_xyz` (
 
  `id` int(11) unsigned NOT NULL AUTO_INCREMENT,
 
  `object_id` int(11) unsigned NOT NULL,
 
  `last_modified` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
 
  `deleted` tinyint(1) NOT NULL DEFAULT '0',
 
  `created_on` timestamp NOT NULL DEFAULT '1970-01-01 00:00:01',
 
  PRIMARY KEY (`id`),
 
  UNIQUE KEY `uq_object_id` (`object_id`),
 
  KEY `last_modified` (`last_modified`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci;

this works correctly the majority of the time:

insert into table_xyz (object_id) values (44);
 
update table_xyz set deleted = 1 where id in (1) and deleted = 0;

occasionally, mariadb just seems to ignore the ON UPDATE CURRENT_TIMESTAMP clause though. here is an excerpt from our binlog with annotated row events. the table was updated at 180319 1:13:12 (utc) which is later than the epoch shows below. column 13 corresponds to `last_modifed`. note that column 13 is not changed in the row update in the binlog (to be clear, it is not changed on the master server itself either). 1521337159 (the existing value of the row when the update occurred) is March 18, 2018 1:39:19 AM which is before the event shown here.

# at 945450098
 
#180319  1:13:12 server id 371  end_log_pos 945450138   GTID 0-371-5349209007 cid=6416620345 trans
 
/*!100001 SET @@session.gtid_seq_no=5349209007*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 945450138
 
...
 
#180319  1:13:12 server id 371  end_log_pos 945450884   Annotate_rows:
 
#Q> /*trace_id:3a3cdc48756e1528,span_id:de5181b87d8857b7,application:abc:LineItemController,action:doDelete,timestamp:1521421992*/ UPDATE db.table_xyz SET deleted = 1 WHERE id  IN (432854801) AND object_type = 'xyz_abc' AND deleted = 0
 
#180319  1:13:12 server id 371  end_log_pos 945450974   Table_map: `db`.`table_xyz` mapped to number 25 (has triggers)
 
# at 945450974
 
#180319  1:13:12 server id 371  end_log_pos 945451136   Update_rows: table id 25 flags: STMT_END_F
 
### UPDATE `db`.`table_xyz`
 
### WHERE
 
###   @1=432854801
 
###   @2=1
 
###   @3=8
 
###   @4=3
 
###   @5=5543740
 
###   @6=2759860
 
###   @7=NULL
 
###   @8=85000
 
###   @9=NULL
 
###   @10=6538
 
###   @11=1.00
 
###   @12=-4 (252)
 
###   @13=1521337159
 
###   @14=0
 
###   @15=1
 
###   @16=1
 
###   @17=NULL
 
###   @18='US/Eastern'
 
###   @19=1
 
###   @20=1521336850
 
###   @21=NULL
 
###   @22=NULL
 
### SET
 
###   @1=432854801
 
###   @2=1
 
###   @3=8
 
###   @4=3
 
###   @5=5543740
 
###   @6=2759860
 
###   @7=NULL
 
###   @8=85000
 
###   @9=NULL
 
###   @10=6538
 
###   @11=1.00
 
###   @12=-4 (252)
 
###   @13=1521337159
 
###   @14=1
 
###   @15=1
 
###   @16=1
 
###   @17=NULL
 
###   @18='US/Eastern'
 
###   @19=1
 
###   @20=1521336850
 
###   @21=NULL
 
###   @22=NULL
 
# at 945451136
 
# at 945451410
 
...
 
#180319  1:13:12 server id 371  end_log_pos 945456124   Xid = 6416620548
 
COMMIT/*!*/;

at regular intervals we have application logic that builds complete snapshots of states of numerous objects. we detect faults when there are clear violations of object states between parent-child object relationships. so it is likely this logic is catching every occurrence of this issue on tables where we have those relationships whereas many users may not be noticing if this happens. of course, we also have many tables that don't have such relationships so in those cases we may not be aware this is even happening.

I have found two somewhat slightly related tickets which I have linked. also note that we recently upgraded from version 10.0.20 to 10.1.28. we were not experiencing this issue while on version 10.0.20. our application logic has not changed since we upgraded to 10.1.28.

Is there some sequence of events that could cause this? any known related issues that might explain it?? thanks!!

 Comments   
Comment by Elena Stepanova [ 2018-10-05 ]

Is it still happening?
The table in question has triggers. What do these triggers do?
Could you please provide the output of SHOW GLOBAL VARIABLES?

Comment by chad ambrosius [ 2018-11-13 ]

elenst, we reverted to 10.0.20 (on centos) shortly after we realized this was happening and couldn't explain it. we have not observed similar issues on 10.1.28 (on ubuntu). note the caveats above though about it being somewhat hard to detect--that said, after this amount of time though, I think it's extremely unlikely we would have not seen similar issues if the same behavior occurred on 10.0.20.

the table has one trigger on insert with action timing BEFORE. it checks some object_type values in other tables and sets an object_type_id or object_type column to certain values. it also sets a created_on column to now() if created_on would otherwise have the default value (see table definition above in description). the 'last_modified' column does not appear anywhere in the trigger.

we are also close to deploying a sort of proxy tool that will send all client traffic to multiple hosts (on different mariadb versions, for example) so that we can better troubleshoot this.

Comment by chad ambrosius [ 2018-11-13 ]

I have attached the global variable output from a host in the same "collection" so apart from some master/slave-type variables, the variables should be the same.

Comment by Elena Stepanova [ 2018-12-31 ]

You said that your checks detect discrepancies, do you happen to have more examples of not updated timestamps (old time and current time which wasn't set)?

One of usual suspects with timestamp issues is DST. It turns out that there is one location where DST switch happened on March 18th between 1 and 3 AM: Troll Station, Antarctica, which otherwise uses GMT (UTC+0). While I hope that's now where you are located, I'd like to rule out some peculiar bug around DST changes, wrong schedule detection, or something of the kind.

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