Debian Wheezy, amd64

Here is what I think happened, which explains most of the story above.

MariaDB [test]> select @@time_zone;

+-----------------+

| @@time_zone     |

+-----------------+

| America/Chicago |

+-----------------+

1 row in set (0.00 sec)

set timestamp = 1478415687; # back to past

MariaDB [test]> create table t1 (t timestamp not null default current_timestamp);

Query OK, 0 rows affected (0.02 sec)

MariaDB [test]> insert into t1 values (null);

Query OK, 1 row affected (0.03 sec)

MariaDB [test]> select t, unix_timestamp(t) from t1;

+---------------------+-------------------+

| t                   | unix_timestamp(t) |

+---------------------+-------------------+

| 2016-11-06 01:01:27 |        1478415687 |

+---------------------+-------------------+

1 row in set (0.00 sec)

SET TIMESTAMP=1478415687/*!*/;

...

create table t1 (t timestamp not null default current_timestamp)

/*!*/;

# at 372

#161106  1:01:27 server id 1  end_log_pos 440   Query   thread_id=12    exec_time=15445981      error_code=0

SET TIMESTAMP=1478415687/*!*/;

BEGIN

/*!*/;

# at 440

# at 481

#161106  1:01:27 server id 1  end_log_pos 481   Table_map: `test`.`t1` mapped to number 55

#161106  1:01:27 server id 1  end_log_pos 515   Write_rows: table id 55 flags: STMT_END_F

### INSERT INTO `test`.`t1`

### SET

###   @1=1478415687

# at 515

#161106  1:01:27 server id 1  end_log_pos 542   Xid = 244

COMMIT/*!*/;

MariaDB [test]> select @@time_zone;

+-----------------+

| @@time_zone     |

+-----------------+

| America/Chicago |

+-----------------+

1 row in set (0.00 sec)

MariaDB [test]> select t, unix_timestamp(t) from t1;

+---------------------+-------------------+

| t                   | unix_timestamp(t) |

+---------------------+-------------------+

| 2016-11-06 01:01:27 |        1478412087 |

+---------------------+-------------------+

1 row in set (0.00 sec)

So, no special magic is involved, and the timestamp already differs. In fact, it's not that easy to squeeze 1478415687 into the table. If instead of relying on the default value on the master, we would try to insert it explicitly, we'd see the difference on the master already:

MariaDB [test]> create table t2 like t1;

Query OK, 0 rows affected (0.00 sec)

MariaDB [test]> insert into t2 values(from_unixtime('1478415687'));

Query OK, 1 row affected (0.01 sec)

MariaDB [test]> select t, unix_timestamp(t) from t2;

+---------------------+-------------------+

| t                   | unix_timestamp(t) |

+---------------------+-------------------+

| 2016-11-06 01:01:27 |        1478412087 |

+---------------------+-------------------+

1 row in set (0.00 sec)

So, the value 1478412087 inserted on the slave in the episode 3 is not surprising. As you said, indeed, 1478415687 and 1478412087 in this timezone mean the same time.

Why mysqlbinlog shows 1478415687 while in fact 1478412087 is inserted – it's a question to internals, my guess is there are too many conversions from/to UNIX timestamp happening on the way. I'll pass it over to serg to decide whether it's wrong, maybe it is.

One thing that you mentioned that I couldn't reproduce right away was this:

"I attempted to fix it by updating the master to increment the created timestamp by one second. Since I'm doing row-based replication, that should cause the right value to propagate to the slave. But it doesn't: on both master and slave the value is incremented by one second, but the hour offset remains."

I was trying to do it via UPDATE t1 SET t = t+1.

Depending on the combination of the current time/zones, it would either cause the master to have 1478412088 (and the slave, consequently), or it would make the replication abort due to the "row not found" error. However, there are many combinations and more than one way to increment the timestamp, it's quite possible that you did it the way that caused the result that you've described. In any case, it's not particularly important since the problem has started long time before that.

Elena,

Thank you very much for taking a look at this!

The extra bit that I think your analysis is missing is that the session time zone was "PST8PDT" when this timestamp was inserted. So in the session timezone, 1478415687 is not a weird timestamp, and there shouldn't be any problem squeezing that value into a table. The problem seems to be a result of the system's timezone being weird at that moment. I agree that 1478415687 might be hard to squeeze into a table in "America/Chicago"/"CST6CDT". But in "PST8PDT", it shouldn't be. Or am I wrong?

For the part where I was unable to fix it by incrementing the timestamp: I'm not sure that's so easily dismissed. It sounds to me like it may actually be the same problem happening again. If the binlog contains a specific UNIX timestamp, and what gets recorded in the slave is a different UNIX timestamp, simply because the system was undergoing a DST change at the time, then something is very weird and wrong. And it sounds almost exactly like the "main" problem.

I was updating the timestamp via "created = created + INTERVAL 1 SECOND". But I don't think that should matter, as long as the row-based binlog shows the correct UNIX time, which it does. It's the slave that's doing something weird with it.

Hmm, I cannot repeat it. Here's what I tried:

set global time_zone='Europe/Moscow';

set time_zone='Europe/Moscow';

-- now, use a session time_zone on the master where timestamp is unambiguous

set time_zone='UTC';

create table t1 (a timestamp);

-- 1288477526 == 2010-10-31 02:25:26 Europe/Moscow

set timestamp=1288477526;

insert t1 values ();

set timestamp=1288477526+3600;

insert t1 values ();

-- note, inserted values differ

select * from t1;

set global time_zone='Europe/Moscow';

set time_zone='Europe/Moscow';

-- this starts slave thread with the time_zone = Europe/Moscow

start slave;

-- wait until it catches up

-- note, values on the slave *look* identical

select * from t1;

set time_zone='UTC';

-- but in a different time zone they're not

select * from t1;

Hello Sergei,

Thank you for looking into this.

I also can't re-create this problem. And for the most part, it didn't take place: virtually all timestamps in this situation were handled correctly.

But there are something like a couple of dozen rows which were bitten by this behavior. And not only that, but the behavior continues: when the binary log tells the slave to update to a new timestamp (a specific timestamp, not an offset), then it still handles the timestamp incorrectly.

That's what makes me think it's worth digging into further. I can fix my slave by manually setting the timestamp, and that would very likely be the end of my problem. I'm leaving it unfixed for now in case it's helpful for diagnosing this.

Please let me know what other information I can provide, or if you don't think it's worth investigating further, I'll just fix my data and move on.

It appears to be important which server versions participate in replication. 5.5 => 10.1 and 10.0 => 10.1 exhibit the problem; 5.5 => 5.5, 5.5 => 10.0, 10.0 => 10.1 and 10.1 => 10.1 don't. I might have made a mistake in one or two combinations, but there is certainly a dependency on the versions.

My scenario below is for 5.5 => 10.1 combination, as in the initial description, but with current 5.5 and 10.1 builds. Maybe some steps are excessive, but executing all of them seems to trigger the result reliably.

• start 5.5 server with default settings on a clean datadir
• load the timezone data, on my machine it's /data/bld/5.5/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3306 mysql
• restart 5.5 server on the same datadir, now with --server-id=1 --port=3306 --log-bin --binlog-format=row --default-time-zone='America/Chicago'
• start 10.1 server with default settings and --port=3307 on a clean datadir
• load the timezone data, /data/bld/10.1/bin/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -uroot --protocol=tcp --port=3307 mysql
• restart 10.1 server on the same datadir, now with --server-id=2 --port=3307 --default-time-zone='America/Chicago'
• connect to 10.1 slave, run

  MariaDB [test]> change master to master_host='127.0.0.1', master_port=3306, master_user='root';

  Query OK, 0 rows affected (0.18 sec)

  MariaDB [test]> start slave;

  Query OK, 0 rows affected (0.00 sec)

• connect to 5.5 master, run

  drop table if exists t1;

  set time_zone = 'PST8PDT';

  set timestamp = 1478415687;

  create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp);

  insert into t1 values (1,null);

  select pk, t, unix_timestamp(t) from t1;

  MariaDB [test]> select pk, t, unix_timestamp(t) from t1;

  +----+---------------------+-------------------+

  | pk | t | unix_timestamp(t) |

  +----+---------------------+-------------------+

  | 1 | 2016-11-06 00:01:27 | 1478415687 |

  +----+---------------------+-------------------+

  1 row in set (0.00 sec)

• connect to 10.1 slave, check the data:

  MariaDB [test]> select pk, t, unix_timestamp(t) from t1;

  +----+---------------------+-------------------+

  | pk | t | unix_timestamp(t) |

  +----+---------------------+-------------------+

  | 1 | 2016-11-06 01:01:27 | 1478412087 |

  +----+---------------------+-------------------+

  1 row in set (0.00 sec)

• connect to 5.5 master, run

  MariaDB [test]> set time_zone = 'PST8PDT';

  Query OK, 0 rows affected (0.00 sec)

  MariaDB [test]> begin;

  Query OK, 0 rows affected (0.00 sec)

  MariaDB [test]> update t1 set t = t + INTERVAL 1 SECOND;

  Query OK, 1 row affected (0.00 sec)

  Rows matched: 1 Changed: 1 Warnings: 0

  MariaDB [test]> commit;

  Query OK, 0 rows affected (0.02 sec)

  MariaDB [test]> select pk, t, unix_timestamp(t) from t1;

  +----+---------------------+-------------------+

  | pk | t | unix_timestamp(t) |

  +----+---------------------+-------------------+

  | 1 | 2016-11-06 00:01:28 | 1478415688 |

  +----+---------------------+-------------------+

  1 row in set (0.00 sec)

• connect to 10.1 slave, check the data:

  MariaDB [test]> select pk, t, unix_timestamp(t) from t1;

  +----+---------------------+-------------------+

  | pk | t | unix_timestamp(t) |

  +----+---------------------+-------------------+

  | 1 | 2016-11-06 01:01:28 | 1478412088 |

  +----+---------------------+-------------------+

  1 row in set (0.00 sec)

Please note that with this scenario, even though we set PST8PDT on the master both times, it's not seen in the binary log:

$ bin/mysqlbinlog --verbose --base64-output=DECODE-ROWS data/ws-bin.000001 

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;

/*!40019 SET @@session.max_insert_delayed_threads=0*/;

/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

DELIMITER /*!*/;

# at 4

#170623 17:38:50 server id 1  end_log_pos 245 	Start: binlog v 4, server v 5.5.57-MariaDB-debug created 170623 17:38:50 at startup

# Warning: this binlog is either in use or was not closed properly.

ROLLBACK/*!*/;

# at 245

#170623 17:41:38 server id 1  end_log_pos 359 	Query	thread_id=4	exec_time=0	error_code=0

use `test`/*!*/;

SET TIMESTAMP=1498228898/*!*/;

SET @@session.pseudo_thread_id=4/*!*/;

SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;

SET @@session.sql_mode=0/*!*/;

SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;

/*!\C utf8 *//*!*/;

SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;

SET @@session.lc_time_names=0/*!*/;

SET @@session.collation_database=DEFAULT/*!*/;

DROP TABLE IF EXISTS `t1` /* generated by server */

/*!*/;

# at 359

#161106  9:01:27 server id 1  end_log_pos 534 	Query	thread_id=4	exec_time=19813211	error_code=0

SET TIMESTAMP=1478415687/*!*/;

create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp)

/*!*/;

# at 534

#161106  9:01:27 server id 1  end_log_pos 602 	Query	thread_id=4	exec_time=19813211	error_code=0

SET TIMESTAMP=1478415687/*!*/;

BEGIN

/*!*/;

# at 602

# at 644

#161106  9:01:27 server id 1  end_log_pos 644 	Table_map: `test`.`t1` mapped to number 33

#161106  9:01:27 server id 1  end_log_pos 682 	Write_rows: table id 33 flags: STMT_END_F

### INSERT INTO `test`.`t1`

### SET

###   @1=1

###   @2=1478415687

# at 682

#161106  9:01:27 server id 1  end_log_pos 709 	Xid = 23

COMMIT/*!*/;

# at 709

#170623 17:43:24 server id 1  end_log_pos 777 	Query	thread_id=6	exec_time=0	error_code=0

SET TIMESTAMP=1498229004/*!*/;

BEGIN

/*!*/;

# at 777

# at 819

#170623 17:43:22 server id 1  end_log_pos 819 	Table_map: `test`.`t1` mapped to number 33

#170623 17:43:22 server id 1  end_log_pos 867 	Update_rows: table id 33 flags: STMT_END_F

### UPDATE `test`.`t1`

### WHERE

###   @1=1

###   @2=1478415687

### SET

###   @1=1

###   @2=1478415688

# at 867

#170623 17:43:24 server id 1  end_log_pos 894 	Xid = 38

COMMIT/*!*/;

DELIMITER ;

# End of log file

ROLLBACK /* added by mysqlbinlog */;

/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

I've also repeated it by running this in 5.5:

source include/have_binlog_format_row.inc;

set global time_zone='Europe/Moscow';

set time_zone='Europe/Moscow';

set time_zone='UTC';

create table t1 (pk int primary key, t timestamp not null default current_timestamp on update current_timestamp);

set timestamp = 1288477526;

insert into t1 values (1,null);

set timestamp = 1288481126;

insert into t1 values (2,null);

And loading the binlog into 10.1 with

source include/have_binlog_format_row.inc;

set global time_zone='Europe/Moscow';

set time_zone='Europe/Moscow';

set time_zone='UTC';

--exec $MYSQL_BINLOG /path/to/5.5/mysql-test/var/mysqld.1/data/master-bin.000001 | $MYSQL

select pk, t, unix_timestamp(t) from t1;

set time_zone=default;

select pk, t, unix_timestamp(t) from t1;

What happens here, 5.5 creates a table with MYSQL_TYPE_TIMESTAMP field, Field_timestamp. But 10.1 creates for the same CREATE TABLE statement a MYSQL_TYPE_TIMESTAMP2 field, Field_timestampf. And table_def::compatible_with() notices that field types differ and creates a conversion table. When a conversion table exists, unpack_row() uses Copy_field interface, and do_field_temporal() works via MYSQL_TIME structure.

Sent review suggestion to maria-developers@