MySQL Bugs: #23966: timestamp replication failure across two timezones

Bug #23966	timestamp replication failure across two timezones
Submitted:	3 Nov 2006 23:34	Modified:	25 Dec 2010 10:07
Reporter:	Doug Campanella	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.27, 5.0.51a	OS:	Linux (Linux)
Assigned to:		CPU Architecture:	Any

Description:
I am not sure what the cause is here, but for some reason replication to Slackware 11 is breaking the timestamps in a replication setup across timezones.  All servers are running MySQL 5.0.27 compiled from source with basic config settings:

Redhat 9/Fedora Core 5
CFLAGS="-O3" CXX=gcc CXXFLAGS="-O3 -felide-constructors -fno-exceptions -fno-rtti" ./configure --prefix=/usr/local/mysql --with-unix-socket-path=/var/lib/mysql/mysql.sock --enable-thread-safe-client --enable-assembler --with-mysqld-ldflags=-all-static

Master Server 1 - gcc (GCC) 3.2.2 20030222 (Red Hat Linux 3.2.2-5) - libc 2.3.2 - kernel 2.4.20
Slave A - gcc (GCC) 4.1.0 20060304 (Red Hat 4.1.0-3) - libc 2.4 - kernel 2.6.17

Slackware 11
CFLAGS="-O3" CXX=gcc CXXFLAGS="-O3 -felide-constructors -fno-exceptions -fno-rtti" ./configure --prefix=/usr/local/mysql --enable-thread-safe-client --enable-assembler --with-mysqld-ldflags=-all-static

Master Server 2 - Slave B - Slave C - gcc (GCC) 3.4.6 - libc 2.3.6 - kernel 2.6.18

All servers are SMP, but I don't think this is related.

How to repeat:
Topology is as follows:

Slave A <- Master Server 1 <-> Master Server 2 -> Slave B -> Slave C

Slave A (Fedora Core 5) has the time_zone variable set to US/Eastern and system_time_zone set to PST.
Master Server 1 (Redhat 9) has the time_zone variable set to SYSTEM and system_time_zone set to EST.
Master Server 2 (Slackware 11) has the time_zone variable set to US/Eastern and system_time_zone set to PST.
Slave B (Slackware 11) has the time_zone variable set to US/Eastern and system_time_zone set to PST.
Slave C (Slackware 11) has the time_zone variable set to US/Eastern and system_time_zone set to PST.

Replication between Master Server 1 and Slave A functions without a problem.

Replication between Master Server 1 and Master Server 2 with the same combination of time zone variables as Slave A results in an error equal to the difference in their system_time_zones when data is INSERTED/UPDATED on Master Server 1.

Data INSERTED/UPDATED on Master Server 2 is replicated properly to Master Server 1.

After changing the system timezone to EST on Master Server 2 the problem moved to Slave B and likewise to Slave C when Slave B was changed to EST.

Does anyone have any idea on what could be going on here?  The only difference in config that I saw between Slave A and Master Server 2 is Master server 2 has log_slave_updates turned on.

Changed Category to Replicaton

I am adding some example test queries/results.  I found that if the time_zone variable is changed to US/Eastern on Master 1 then the replication works correctly to all servers.

Update command on Master 1 with time_zone = SYSTEM.

mysql> update listings set whentime='20061112030000' where listingid=212785;
Query OK, 1 row affected (0.59 sec)
Rows matched: 1  Changed: 1  Warnings: 0

Results on Slave A:
mysql> select whentime from listings where listingid='212785';
+---------------------+
| whentime            |
+---------------------+
| 2006-11-12 03:00:00 |
+---------------------+
1 row in set (0.00 sec)

Results on Master 2 system_time_zone=PST:
mysql> select whentime from listings where listingid='212785';
+---------------------+
| whentime            |
+---------------------+
| 2006-11-12 06:00:00 |
+---------------------+
1 row in set (0.00 sec)

Change time_zone for session to US/Eastern and executed the same command on Master 1:

mysql> set time_zone='US/Eastern';
Query OK, 0 rows affected (0.15 sec)

mysql> update listings set whentime='20061112030000' where listingid=212785;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0

Results from Slave A:

mysql> select whentime from listings where listingid='212785';
+---------------------+
| whentime            |
+---------------------+
| 2006-11-12 03:00:00 |
+---------------------+
1 row in set (0.00 sec)

Results from Master 2:

mysql> select whentime from listings where listingid='212785';
+---------------------+
| whentime            |
+---------------------+
| 2006-11-12 03:00:00 |
+---------------------+
1 row in set (0.00 sec)

Thank you for a problem report, and sorry for a delay with its processing. 

As you are compiling from source, please, try to compile and check newer version, 5.0.33. Inform about the results.

I will do what I can to test this.  I just pulled master 1 from service and deleted all mysql data from that server (it was a rented one).  Wish you had caught me last week.  I am not sure how long I will have access to it, as it has been canceled.  I will have to set up a second mysql slave on one of the slackware machines with PST timezone as well (they are currently running 5.0.32). I will try to setup another test (for failure) with 5.0.27 on both and then compile a copy of 5.0.33 on both to test your changes.

Please, inform about the results of your tests.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Do you still have the same problem with 5.0.33 or 5.0.37?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

I have verified the same problem as occuring in 5.0.51a-community-log. It appears replication will fail on a timestamp column if the timezone of the master and slave differ.

My replication setup is not as complicated as the one referenced in the original bug report. I have a master in London running 5.0.51a-community-log and a slave in the US also running 5.0.51a-community-log. Both using the RHEL5 RPMs on CentOS 5.

(on slave)
mysql> show slave status\G;
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 63.172.126.245
                Master_User: replslave
                Master_Port: 3307
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000003
        Read_Master_Log_Pos: 355576082
             Relay_Log_File: mysql-backup-us1-relay-bin.000008
              Relay_Log_Pos: 580154187
      Relay_Master_Log_File: mysql-bin.000002
           Slave_IO_Running: Yes
          Slave_SQL_Running: No
            Replicate_Do_DB:
        Replicate_Ignore_DB:
         Replicate_Do_Table:
     Replicate_Ignore_Table:
    Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
                 Last_Errno: 1292
                 Last_Error: Error 'Incorrect datetime value: '2006-04-02 02:34:22' for column 'TTTS' at row 1' on query. Default database: 'trace2'. Query: 'REPLACE INTO trace2.THIRDPARTYTRANS VALUES ('192       ','B    ',992836,'2006-04-02 02:34:22','096A7289-DD49-88FA-7E3E-E6394611453D','583A7C3D-3048-72D1-795B-FB811B332D08')'
               Skip_Counter: 0
        Exec_Master_Log_Pos: 580154050
            Relay_Log_Space: 1429336771
            Until_Condition: None
             Until_Log_File:
              Until_Log_Pos: 0
         Master_SSL_Allowed: No
         Master_SSL_CA_File:
         Master_SSL_CA_Path:
            Master_SSL_Cert:
          Master_SSL_Cipher:
             Master_SSL_Key:
      Seconds_Behind_Master: NULL
1 row in set (0.00 sec)

ERROR:
No query specified

Running the query referenced above driectly on the slave yeilds success; however, using the skip counter to advance the replication position in the binlog only causes the same error on the next row.

mysql> REPLACE INTO trace2.THIRDPARTYTRANS VALUES ('192       ','B    ',992836,'2006-04-02 02:34:22','096A7289-DD49-88FA-7E3E-E6394611453D','583A7C3D-3048-72D1-795B-FB811B332D08');
Query OK, 1 row affected, 1 warning (0.11 sec)

Upon changing the timezone (replaced /etc/localtime) on the slave to the same as the master (BST) and restarting the slave, the problem was resolved:

mysql> show slave status\G;
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 63.172.126.245
                Master_User: replslave
                Master_Port: 3307
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000003
        Read_Master_Log_Pos: 355587235
             Relay_Log_File: mysql-backup-us1-relay-bin.000008
              Relay_Log_Pos: 592649593
      Relay_Master_Log_File: mysql-bin.000002
           Slave_IO_Running: Yes
          Slave_SQL_Running: Yes
            Replicate_Do_DB:
        Replicate_Ignore_DB:
         Replicate_Do_Table:
     Replicate_Ignore_Table:
    Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
                 Last_Errno: 0
                 Last_Error:
               Skip_Counter: 0
        Exec_Master_Log_Pos: 592649456
            Relay_Log_Space: 1429348336
            Until_Condition: None
             Until_Log_File:
              Until_Log_Pos: 0
         Master_SSL_Allowed: No
         Master_SSL_CA_File:
         Master_SSL_CA_Path:
            Master_SSL_Cert:
          Master_SSL_Cipher:
             Master_SSL_Key:
      Seconds_Behind_Master: 236745
1 row in set (0.00 sec)

ERROR:
No query specified

Here's the schema of the table in question:
mysql> describe trace2.THIRDPARTYTRANS;
+-------------+--------------+------+-----+-------------------+-------+
| Field       | Type         | Null | Key | Default           | Extra |
+-------------+--------------+------+-----+-------------------+-------+
| TTTPCODE    | char(10)     | NO   | PRI | NULL              |       |
| TTEVENT     | char(5)      | NO   | PRI | NULL              |       |
| TTRFNBR     | bigint(19)   | NO   | PRI | NULL              |       |
| TTTS        | timestamp    | NO   |     | CURRENT_TIMESTAMP |       |
| TTCUSTOMER  | varchar(132) | NO   | PRI | NULL              |       |
| TTSESSIONID | varchar(132) | NO   | PRI | NULL              |       |
+-------------+--------------+------+-----+-------------------+-------+
6 rows in set (0.04 sec)

To repeat:
 Create a table on the master with a timestamp column. Create a slave on a system set to a different timezone. Insert rows into the master. The rows will not replicate and the slave status will report error 1292 with 'Incorrect datetime value'. Reset the timezone on the slave to match the master. Restart the slave. Slave continues to read master binlog without error and the data is replicated.

Thank you for the feedback.

I can not repeat described behavior with test data. Please provide output of  show variables like '%time_zone%'; on both master and slave.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Replication fails when in the master database there are records with timestamp values that do not exist in the slave timezone and it happens during adjusting clock to daylight saving time. In my case master server is in CDT timezone (from 14, March). Slave server went from MSK to MSD on 29, March at 02:00 local time. So timestamp values between 2010-03-29 02:00:00 and 2010-03-29 02:59:59 cause replication failure.

Both freeBSD servers have mysql-server-5.1.38 installed.

Julia,

thank you for the feedback. Please provide output of SHOW CREATE TABLE problem table and row with different values on master and slave.

CREATE TABLE `stats_visit_action` (
  `visit_action_id` int(11) unsigned NOT NULL AUTO_INCREMENT,
  `visit_id` int(11) unsigned NOT NULL,
  `action_id` int(11) unsigned NOT NULL,
  `type` tinyint(3) unsigned NOT NULL,
  `datetime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`visit_action_id`),
  KEY `date` (`datetime`),
  KEY `action_type` (`action_id`,`type`)
) ENGINE=InnoDB AUTO_INCREMENT=709064 DEFAULT CHARSET=utf8;

Unfortunately I can't get replication error now, but it was something like this

Incorrect datetime value: '2010-03-38 02:00:05' for column 'datetime'... 

in this query:
INSERT INTO ispring4.stats_visit_action VALUES ('345678', '6899034', '97897955', 0, '2010-03-28 02:00:05')

Sorry, it's an error in my previous post in the date value. You should read

Incorrect datetime value: '2010-03-28 02:00:05' for column 'datetime'...

Thank you for the feedback.

Replication should convert timezones. Also version 5.1.38 and I can not repeat described behavior in my environment. Please try current version 5.1.45 and if problem still exists provide configuration files for both master and slave. Also, please, compare if one of servers has clock which go fast or slow.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

MASTER

mysql> SELECT datetime_insert FROM LOG_MAIL WHERE pk = 26556140;
+---------------------+
| datetime_insert |
+---------------------+
| 2010-10-21 10:10:14 | 
+---------------------+
1 row in set (0.00 sec)

We encounter the same problem now, since we use localized dates heavily now
we literally switch timezone every connection.

SLAVE

mysql> SELECT datetime_insert FROM LOG_MAIL WHERE pk = 26556140;
+---------------------+
| datetime_insert |
+---------------------+
| 2010-10-21 04:10:14 | 
+---------------------+
1 row in set (0.00 sec)

This is the binlog replicated to the slave:

#101021 10:10:14 server id 172 end_log_pos 3700159 Intvar
SET INSERT_ID=26556140/*!*/;
# at 3700159
#101021 10:10:14 server id 172 end_log_pos 3706668 Query	thread_id=97	exec_time=0	error_code=0
SET TIMESTAMP=1287648614/*!*/;
INSERT DELAYED INTO LOG_MAIL (
            client_pk, mailtype, mail_from, mail_to, mail_subject, mail_body, initiator, datetime_insert
        ) VALUES (
            '0', 'email', 'info@abc.com', '123@gmx.de', 'Subject', 'body', 'sweepstake.pl', NOW() );

looks right...
but in the slave log we read:
#101021 10:10:14 server id 172 end_log_pos 4544696 Intvar
SET INSERT_ID=26556140/*!*/;
# at 4544696
#101021 10:10:14 server id 172 end_log_pos 4551222 Query	thread_id=97	exec_time=0	error_code=0
SET TIMESTAMP=1287648614/*!*/;
SET @@session.time_zone='America/Detroit'/*!*/;
INSERT DELAYED INTO LOG_MAIL (
            client_pk, mailtype, mail_from, mail_to, mail_subject, mail_body, initiator, datetime_insert
        ) VALUES (
'0', 'email', 'info@abc.com', '123@gmx.de', 'Subject', 'body', 'sweepstake.pl', NOW() );

so the replication user gests a session variable (leaking from somewhere else?), which is not effective in the master replication.

Andreas,

thank you for the feedback. What query show variables like '%time_zone%'; outputs in your environment on both master and slave?

Hi Svetlana,
This is the master:

Server version: 5.0.51a-24+lenny4-log (Debian)
mysql> show variables like '%time_zone%'; 
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| system_time_zone | CEST   | 
| time_zone        | SYSTEM | 
+------------------+--------+
2 rows in set (0.00 sec)
mysql> select NOW(); 
+---------------------+
| NOW()               |
+---------------------+
| 2010-10-21 12:09:41 | 
+---------------------+

This is the slave:
Server version: 5.0.51a-24+lenny4-log (Debian)
mysql>  show variables like '%time_zone%'; 
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| system_time_zone | CEST   | 
| time_zone        | SYSTEM | 
+------------------+--------+

mysql> select NOW(); 
+---------------------+
| NOW()               |
+---------------------+
| 2010-10-21 12:10:15 | 
+---------------------+

Thank you for the feedback.

Looks weird what you have such entry in slave relay log. Please try current version 5.0.91 available from dev.mysql.com/downloads: we consistently fix bugs and this problem can be fixed already.

Hi Sveta,
thank you for your effort.
I checked the changelogs, but found no note about this bug being fixed between 5.0.51 and 5.0.91.

Due to the age of this problem, i guess, this is hard to replicate, and therefore still unfound ...

I will check with 5.0.91 and 5.1.51, but  in the meantime i'll explain detailed, what we do - maybe you get an idea where it might come from.

We have servers running in Master/Slave replication, with databases which store data from different countries.

on each connect (no matter if master or slave) we do "set time_zone = $country_tz". we also change it rapidly during the session, because we also have persistent connections.

The insert is right on the master, but the Data in the slave-db is invalid. 
Also in the slave binlog ( we have log-slave-updates set on ) we have a wrong TZ-Setting that does not appear in the binlog of the Master.

It looks like, the TZ-Setting on the slave is leaking somehow into the replication-connection, but i was not able to reproduce it.
I checked, if "set global" is used somewhere, but it's not.

i should note, the problems seems to be intermittent for us, as we also have correct entries. But a short lookup showed about 20% wrong dates.

I think we have it.
this is the masters binlog:
#101021 19:36:10 server id 172  end_log_pos 54632870    Query   thread_id=39315128      exec_time=0     error_code=0
use company_my_log/*!*/;
SET TIMESTAMP=1287682570/*!*/;
SET @@session.time_zone='Asia/Kuala_Lumpur'/*!*/;
INSERT DELAYED INTO LOG_OPTIN_CHANGES
SET INSERT_ID=1165056/*!*/;
#101021 19:36:10 server id 172  end_log_pos 54633253    Query   thread_id=39315128      exec_time=0     error_code=0
SET TIMESTAMP=1287682570/*!*/;
INSERT DELAYED INTO LOG_OPTIN_CHANGES
SET INSERT_ID=26584310/*!*/;
#101021 19:36:10 server id 172  end_log_pos 54635150    Query   thread_id=39137459      exec_time=0     error_code=0
use company_com_log/*!*/;
INSERT DELAYED INTO LOG_MAIL

but company is in a different timezone.

What seems to happen here:
the sesssion.time_zone is copied to the replication user.
But it is not reliable reset if the thread_id changes.

But for my understanding, session.time_zone should be bound to the thread, and if threads change, replication should auomatically aquire the timezone from this thread.

Thank you for the feedback.

This looks very similar to bug #41719 which is fixed in version 5.0.80. Please upgrade and confirm your issue is fixed as well.

i currently use 5.0.91 - as suggested by you.
I am sorry, its obviuosly not fixed or another bug.

please disregard - we will update to 5.1.51. and test again..

Thank you for the feedback.

> please disregard - we will update to 5.1.51. and test again..

We are waiting either results of tests in 5.1.51 or confirmation it still exists in 5.0.91. Last 2 comments a bit confusing if read together.

Good afternoon,
sincce this issue hapens on the master, we werent able to switch to 5.0.91. because 5.0 support will be deprecated in near future.

but I have read the binlogs and can confirm its a duplicate of #41719.
We switched to 5.1.51 instead and i confirm and it is fixed in 5.1.51.

Thank you for your help.

Thank you for the feedback.

Closed as duplicate of bug #41719