gh-ost: Incorrect datetime value: '1970-01-01 00:00:00' for column 'create_time'

**https://dev.mysql.com/doc/refman/5.7/en/datetime.html The TIMESTAMP data type is used for values that contain both date and time parts. TIMESTAMP has a range of ‘1970-01-01 00:00:01’ UTC to ‘2038-01-19 03:14:07’ UTC.

Caused by :1970-01-01 00:00:00 is not in the range of timestamp. **

How to repeat:

mysql version:5.5.44-log

create database mysqlslap charset utf8;

CREATE TABLE test11 (
  id bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT '',
  create_time timestamp NULL DEFAULT '0000-00-00 00:00:00',
  update_time timestamp NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  counter int(10) unsigned DEFAULT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8;

insert into test11 values (1,'0000-00-00 00:00:00',now(),0);

3.create sql for test. more gh-ost_test.sql update test11 set counter=counter+1 where id=1;

  1. use mysqlslap for update mysqlslap -uroot -proot123 -h127.0.0.1 --port=3309 test -c 10 --query=gh-ost_test.sql --number-of-queries=1000000;

5.while mysqlslap is runing, in new window execute gh-ost . /apps/sh/gh-ost -user="root" -password=root123 -host=127.0.0.1 -port=3309 -allow-on-master --initially-drop-old-table -database="mysqlslap" -table="test11" -alter="add column name varchar(1)" -execute

6.logs:

2018/01/22 18:06:07 binlogsyncer.go:75: [info] create BinlogSyncer with config &{99999 mysql 127.0.0.1 3309 root root123  false false <nil>}
2018/01/22 18:06:07 binlogsyncer.go:241: [info] begin to sync binlog from position (mysql-bin.000003, 16900979)
2018/01/22 18:06:07 binlogsyncer.go:134: [info] register slave for master server 127.0.0.1:3309
2018/01/22 18:06:07 binlogsyncer.go:568: [info] rotate to (mysql-bin.000003, 16900979)
\# Migrating `mysqlslap`.`test11`; Ghost table is `mysqlslap`.`_test11_gho`
\# Migrating mysql-gs-qmduz.vclound.com:3309; inspecting mysql-gs-qmduz.vclound.com:3309; executing on mysql-gs-qmduz.vclound.com
\# Migration started at Mon Jan 22 18:06:07 +0800 2018
\# chunk-size: 1000; max-lag-millis: 1500ms; max-load: ; critical-load: ; nice-ratio: 0.000000
\# throttle-additional-flag-file: /tmp/gh-ost.throttle 
\# Serving on unix socket: /tmp/gh-ost.mysqlslap.test11.sock
Copy: 0/1 0.0%; Applied: 0; Backlog: 0/100; Time: 0s(total), 0s(copy); streamer: mysql-bin.000003:16908098; State: migrating; ETA: N/A
2018-01-22 18:06:07 ERROR Error 1292: Incorrect datetime value: '1970-01-01 00:00:00' for column 'create_time' at row 1; query=
                        update /* gh-ost `mysqlslap`.`_test11_gho` */
                                        `mysqlslap`.`_test11_gho`
                                set
                                        `id`=?, `create_time`=?, `update_time`=?, `counter`=?
                                where
                                        ((`id` = ?))
                ; args=[1 1970-01-01 08:00:00 +0800 CST 2018-01-22 18:06:07 +0800 CST 41448 1]
Copy: 1/1 100.0%; Applied: 1; Backlog: 100/100; Time: 1s(total), 1s(copy); streamer: mysql-bin.000003:16934720; State: migrating; ETA: due
2018-01-22 18:06:08 ERROR Error 1292: Incorrect datetime value: '1970-01-01 00:00:00' for column 'create_time' at row 1; query=
                        update /* gh-ost `mysqlslap`.`_test11_gho` */
                                        `mysqlslap`.`_test11_gho`
                                set
                                        `id`=?, `create_time`=?, `update_time`=?, `counter`=?
                                where
                                        ((`id` = ?))
                ; args=[1 1970-01-01 08:00:00 +0800 CST 2018-01-22 18:06:07 +0800 CST 41448 1]
Copy: 1/1 100.0%; Applied: 1; Backlog: 100/100; Time: 2s(total), 2s(copy); streamer: mysql-bin.000003:16934720; State: migrating; ETA: due
2018-01-22 18:06:09 ERROR Error 1292: Incorrect datetime value: '1970-01-01 00:00:00' for column 'create_time' at row 1; query=
                        update /* gh-ost `mysqlslap`.`_test11_gho` */
                                        `mysqlslap`.`_test11_gho`
                                set
                                        `id`=?, `create_time`=?, `update_time`=?, `counter`=?
                                where
                                        ((`id` = ?))
                ; args=[1 1970-01-01 08:00:00 +0800 CST 2018-01-22 18:06:07 +0800 CST 41448 1]
Copy: 1/1 100.0%; Applied: 1; Backlog: 100/100; Time: 3s(total), 3s(copy); streamer: mysql-bin.000003:16934720; State: migrating; ETA: due

About this issue

  • Original URL
  • State: open
  • Created 6 years ago
  • Comments: 17 (13 by maintainers)

Most upvoted comments

https://github.com/github/gh-ost/pull/539 attempts to reproduce. I’m confused, though:

These statements:

CREATE TABLE test11 (
  id bigint(20) unsigned NOT NULL AUTO_INCREMENT COMMENT '',
  create_time timestamp NULL DEFAULT '0000-00-00 00:00:00',
  update_time timestamp NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  counter int(10) unsigned DEFAULT NULL,
  PRIMARY KEY (id)
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8;

insert into test11 values (1,'0000-00-00 00:00:00',now(),0);

are both invalid when sql_mode contains NO_ZERO_IN_DATE,NO_ZERO_DATE.

But when setting sql_mode='' the tests introduced in #539 pass and I’m unable to reproduce the error.

My timezone is +02:00 so it should reproduce similar error to that used in +08:00.

Further notes:

The MySQL server is 5.5. With 5.6 there was a change in how timestamps (and dates and datetimes) were stored, to allow for fractions. I don’t know if that’s relevant here.

Thanks @ggunson for pointing this out! It may indeed be relevant. If the representation is also changed in the binary logs, it might be it. In go-mysql there is a distinction between MYSQL_TYPE_DATETIME and MYSQL_TYPE_DATETIME2. I’ve never seen MYSQL_TYPE_DATETIME and always assumed it was some legacy encoding support – it may be a 5.5 encoding?

(assuming gh-ost is using master)

I’ve actually recently diverged, and anecdotally due to a DATETIME encoding issue, see failing PR.

Thank you very much @ggunson for the analysis. I suspect to reproduce the error I’ll need a 5.5 setup.

“the problem is a timestamp, which shouldn’t have any timezone attached to it” is not how it works.

@druud I apologize for being unclear. As stored a timestamp has no timezone attached to it. I’ll amend my earlier comment.

The MySQL timestamp type is physically stored as an epoch-delta, where 1 = “1970-01-01T00:00:01.000000Z”.

Except prior to MySQL 5.6.4 where it was stored without the microseconds.

I believe @liuguoshun 's gh-ost example is:

  1. mysqld is 5.5. I don’t know what version gh-ost is.
  2. mysqld has the settings time_zone='+08:00' and sql_mode=‘’. Zero dates are allowed.
  3. gh-ost is running on the master host, connecting to the master mysqld.
  4. The example table has a timestamp field create_time of default 0/‘0000-00-00…’. Because of the default setting and no ON UPDATE, this value isn’t automatically modified when the row is updated.
  5. The example table only has one row, with create_time= ‘0000-00-00 00:00:00’.
  6. mysqlslap is updating that one row with update test11 set counter=counter+1 where id=1, so create_time isn’t being explicitly updated.
  7. gh-ost is adding a new column to the table, with no change specified to create_time: add column name varchar(1)
  8. (Assumption) gh-ost, when parsing the master’s binary log, is seeing the row event for the UPDATE and converting the after-image create_time ‘0000-00-00 00:00:00’ (however it’s represented in 5.5 row events, I don’t know, 0?) to ‘1970-01-01 08:00:00 +0800 CST’ when it’s applying the update to the new _test11_gho table.

(@liuguoshun please let me know if any of that is wrong).

create_time should just be copied from test11 to _test11_gho without modification, in this example, but it is. I’m hoping this is enough information for @shlomi-noach to know what to ask for from @liuguoshun next.

Thanks for resurrecting this. Since last time, we have set up 5.5 tests in CI, and sure enough, the issue reproduces in CI via https://github.com/github/gh-ost/pull/539. (You cannot see the CI log at this time).

OK what I can try is force 0000-00-00 00:00:00 to not convert and just keep being 0000-00-00 00:00:00. I think it makes sense, but I’ll send it through testing to confirm nothing breaks.