replicated TIMESTAMP filed wrong value on slave

[Muhammad Irfan]

I noticed NOW() doesn't replicate correctly with STATEMENT/MIXED logging with different time zone configured on master/slave. Also, with ROW based logging explicit value for timestamp column and NOW() both doesn't replicates correctly on slave side.

Master:

mysql> CREATE TABLE `testing1` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  `LAST_UPDATE` timestamp NULL DEFAULT NULL,
  PRIMARY KEY (`ID`)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=latin1

```mysql> SHOW GLOBAL VARIABLES LIKE '%version%';
+-------------------------+----------------------------------------------------------+
| Variable_name | Value |
+-------------------------+----------------------------------------------------------+
| innodb_version | 5.5.57-38.9 |
| protocol_version | 10 |
| slave_type_conversions | |
| tls_version | TLSv1.1,TLSv1.2 |
| version | 5.5.57-38.9-log |
| version_comment | Percona Server (GPL), Release 38.9, Revision fc6d4f87a88 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+----------------------------------------------------------+
8 rows in set (0.00 sec)

mysql> SHOW GLOBAL VARIABLES LIKE '%time_zone%';
+------------------+--------+
| Variable_name | Value |
+------------------+--------+
| system_time_zone | EDT |
| time_zone | SYSTEM |
+------------------+--------+
2 rows in set (0.00 sec)

mysql> SHOW GLOBAL VARIABLES LIKE '%binlog_format%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.00 sec)

mysql> INSERT INTO testing1 (LAST_UPDATE) VALUES ('2017-09-26 04:05:00');
Query OK, 1 row affected (0.00 sec)

mysql> INSERT INTO testing1 (LAST_UPDATE) VALUES (NOW());
Query OK, 1 row affected (0.00 sec)

mysql> SELECT * FROM testing1;
+----+---------------------+
| ID | LAST_UPDATE |
+----+---------------------+
| 1 | 2017-09-26 04:05:00 |
| 2 | 2017-09-28 01:55:19 |
+----+---------------------+
2 rows in set (0.00 sec)

mysql> SELECT NOW();
+---------------------+
| NOW() |
+---------------------+
| 2017-09-28 01:55:29 |
+---------------------+
1 row in set (0.00 sec)

Binary log event (master):

# at 183
#170928 1:55:11 server id 1 end_log_pos 211 Intvar
SET INSERT_ID=1/*!*/;
# at 211
#170928 1:55:11 server id 1 end_log_pos 347 Query thread_id=21 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1506578111/*!*/;
INSERT INTO testing1 (LAST_UPDATE) VALUES ('2017-09-26 04:05:00')
/*!*/;
# at 347
#170928 1:55:11 server id 1 end_log_pos 374 Xid = 652
COMMIT/*!*/;
# at 374
#170928 1:55:19 server id 1 end_log_pos 450 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506578119/*!*/;
BEGIN
/*!*/;
# at 450
#170928 1:55:19 server id 1 end_log_pos 478 Intvar
SET INSERT_ID=2/*!*/;
# at 478
#170928 1:55:19 server id 1 end_log_pos 598 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506578119/*!*/;
INSERT INTO testing1 (LAST_UPDATE) VALUES (NOW())
/*!*/;
```

Slave:

mysql> SHOW GLOBAL VARIABLES LIKE '%version%';
+-------------------------+------------------------------------------------------+
| Variable_name | Value |
+-------------------------+------------------------------------------------------+
| innodb_version | 5.5.55-38.8 |
| protocol_version | 10 |
| slave_type_conversions | |
| tls_version | TLSv1.1,TLSv1.2 |
| version | 5.5.55-38.8-log |
| version_comment | Percona Server (GPL), Release 38.8, Revision 11f5bbd |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+------------------------------------------------------+
8 rows in set (0.00 sec)

mysql> SHOW GLOBAL VARIABLES LIKE '%time_zone%';
+------------------+--------+
| Variable_name | Value |
+------------------+--------+
| system_time_zone | MDT |
| time_zone | SYSTEM |
+------------------+--------+
2 rows in set (0.00 sec)

mysql> SELECT * FROM testing1;
+----+---------------------+
| ID | LAST_UPDATE |
+----+---------------------+
| 1 | 2017-09-26 04:05:00 |
| 2 | 2017-09-27 23:55:19 |
+----+---------------------+
2 rows in set (0.00 sec)

Binary log event (slave):

# at 260
#170927 23:55:11 server id 1 end_log_pos 288 Intvar
SET INSERT_ID=1/*!*/;
# at 288
#170927 23:55:11 server id 1 end_log_pos 424 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506578111/*!*/;
INSERT INTO testing1 (LAST_UPDATE) VALUES ('2017-09-26 04:05:00')
/*!*/;
# at 424
#170927 23:55:11 server id 1 end_log_pos 451 Xid = 118
COMMIT/*!*/;
# at 451
#170927 23:55:19 server id 1 end_log_pos 518 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506578119/*!*/;
BEGIN
/*!*/;
# at 518
#170927 23:55:19 server id 1 end_log_pos 546 Intvar
SET INSERT_ID=2/*!*/;
# at 546
#170927 23:55:19 server id 1 end_log_pos 666 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506578119/*!*/;
INSERT INTO testing1 (LAST_UPDATE) VALUES (NOW())
/*!*/;

NOW() didn't replicated master value instead slave server current date and time as per slave timezone with binary logging format STATEMENT or MIXED.

With ROW based logging on master/slave:

Master:

mysql> INSERT INTO testing1 (LAST_UPDATE) VALUES ('2017-09-26 04:05:00');
Query OK, 1 row affected (0.01 sec)

mysql> INSERT INTO testing1 (LAST_UPDATE) VALUES (NOW());
Query OK, 1 row affected (0.00 sec)

mysql> SELECT * FROM testing1;
+----+---------------------+
| ID | LAST_UPDATE |
+----+---------------------+
| 1 | 2017-09-26 04:05:00 |
| 2 | 2017-09-28 02:19:18 |
+----+---------------------+
2 rows in set (0.00 sec)

Slave:

mysql> SELECT * FROM testing1;
+----+---------------------+
| ID | LAST_UPDATE |
+----+---------------------+
| 1 | 2017-09-26 02:05:00 |
| 2 | 2017-09-28 00:19:18 |
+----+----------------------

Binary log event (master):

BEGIN
/*!*/;
# at 183
# at 231
#170928 2:19:11 server id 1 end_log_pos 231 Table_map: `test`.`testing1` mapped to number 37
#170928 2:19:11 server id 1 end_log_pos 269 Write_rows: table id 37 flags: STMT_END_F
### INSERT INTO test.testing1
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=1506413100 /* TIMESTAMP meta=0 nullable=1 is_null=0 */
# at 269
#170928 2:19:11 server id 1 end_log_pos 296 Xid = 621
COMMIT/*!*/;
# at 296
#170928 2:19:18 server id 1 end_log_pos 372 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506579558/*!*/;
BEGIN
/*!*/;
# at 372
# at 420
#170928 2:19:18 server id 1 end_log_pos 420 Table_map: `test`.`testing1` mapped to number 37
#170928 2:19:18 server id 1 end_log_pos 458 Write_rows: table id 37 flags: STMT_END_F
### INSERT INTO test.testing1
### SET
### @1=2 /* INT meta=0 nullable=0 is_null=0 */
### @2=1506579558 /* TIMESTAMP meta=0 nullable=1 is_null=0 */
# at 458
#170928 2:19:18 server id 1 end_log_pos 485 Xid = 628
COMMIT/*!*/;

Binary log event (slave):

BEGIN
/*!*/;
# at 166
# at 214
#170928 0:19:11 server id 1 end_log_pos 214 Table_map: `test`.`testing1` mapped to number 34
#170928 0:19:11 server id 1 end_log_pos 252 Write_rows: table id 34 flags: STMT_END_F
### INSERT INTO test.testing1
### SET
### @1=1 /* INT meta=0 nullable=0 is_null=0 */
### @2=1506413100 /* TIMESTAMP meta=0 nullable=1 is_null=0 */
# at 252
#170928 0:19:11 server id 1 end_log_pos 279 Xid = 498
COMMIT/*!*/;
# at 279
#170928 0:19:18 server id 1 end_log_pos 338 Query thread_id=21 exec_time=0 error_code=0
SET TIMESTAMP=1506579558/*!*/;
BEGIN
/*!*/;
# at 338
# at 386
#170928 0:19:18 server id 1 end_log_pos 386 Table_map: `test`.`testing1` mapped to number 34
#170928 0:19:18 server id 1 end_log_pos 424 Write_rows: table id 34 flags: STMT_END_F
### INSERT INTO test.testing1
### SET
### @1=2 /* INT meta=0 nullable=0 is_null=0 */
### @2=1506579558 /* TIMESTAMP meta=0 nullable=1 is_null=0 */
# at 424
#170928 0:19:18 server id 1 end_log_pos 451 Xid = 506
COMMIT/*!*/;

so different values for both i.e. for TIMESTAMP column with explicit value and with NOW() too both stored as different value on slave side with ROW based logging. I found upstream bug https://bugs.mysql.com/bug.php?id=71016 could be similar.

[Sveta Smirnova (svetasmirnova)]

As upstream bug mentions http://dev.mysql.com/doc/refman/5.6/en/replication-features-timezone.html: "By default, master and slave servers assume that they are in the same time zone. If you are replicating between servers in different time zones, the time zone must be set on both master and slave. Otherwise, statements depending on the local time on the master are not replicated properly, such as statements that use the NOW() or FROM_UNIXTIME() functions. Set the time zone in which MySQL server runs by using the --timezone=timezone_name option of the mysqld_safe script or by setting the TZ environment variable. See also Section 17.4.1.15, “Replication and System Functions”. "

Since you use time_zone SYSTEM behavior with RBR is expected (everything is local to slave). However behavior for SBR/MIXED is not expected as, again, mentioned in the upstream bug:

> [29 Jan 2014 17:26] Jon Stephens
>
> The result that the submitter says that he's obtaining in Step 5--the same column showing the same literal value on both master and slave--is exactly the opposite of what we'd expect. If this happens consistently, it's a bug.

[Sveta Smirnova (svetasmirnova)]

Still repeatable on 5.7

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1824