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

[liuguoshun]

**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:

1. mysql version:5.5.44-log

2. 
   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;`

4. 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 } 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

[shlomi-noach]

Hi, Thank you for the report. I'm afraid there's a few things I'm unsure about here. Please clarify:

1. Where does 1970-01-01 appear in the first place? I see you inserting 0000-00-00 00:00:00.
2. What time zone are you using? CST is central time, which is before UTC, meaning if you're inserting a 1970-01-01 00:00:00 (I don't see where) in CST, that's before 1970-01-01 00:00:00 UTC
3. According to docs 1970-01-01 00:00:00 is invalid, and gh-ost says so, so why is it wrong?

[liuguoshun]

Thanks for the quick reply, 1.I think the "1970-01-01" comes from binlog reading. (If no dml when gh-ost is running,no errors got). 2.MySQL time_zone='+08:00'; 3.As you can see in the log , args is [1 1970-01-01 08:00:00 +0800 CST 2018-01-22 18:06:07 +0800 CST 41448 1], "1970-01-01 08:00:00 +0800 CST" equal to "1970-01-01 00:00:00 UTC", and it's invalid.

[druud]

"1970-01-01 08:00:00 +0800 CST" is an invalid value. Where does it come from?

If the old context was non-strict, and the loading context is strict, then this can happen. So either fix the data, or load in non-strict context (which then keeps the problem around).

[liuguoshun]

Hi druud: I think "1970-01-01 08:00:00 +0800 CST" comes from binlog reading , if no update on the table(that's what setp 4 dose), there is no error.

sql_mode is none and innodb_strict_mode is off. if not I cant't insert the value into table test11 at step 2.

mysql> show variables like 'sql_mode'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | sql_mode | | +---------------+-------+ 1 row in set (0.00 sec) mysql> show variables like 'innodb_strict_mode'; +--------------------+-------+ | Variable_name | Value | +--------------------+-------+ | innodb_strict_mode | OFF | +--------------------+-------+ 1 row in set (0.00 sec)

[ggunson]

So, the column causing the problem is a timestamp, which shouldn't have any timezone attached to it in storage. And it's not getting updated in the update statements, only counter is, but the binlog full image shows the before/after for all columns and somehow this is getting converted.

  create_time timestamp NULL DEFAULT '0000-00-00 00:00:00',

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.

I see from https://github.com/github/gh-ost/blob/master/vendor/github.com/siddontang/go-mysql/replication/row_event.go#L617 (assuming gh-ost is using master) the binlog parser is to parse 0 timestamps as '0000-00-00...'. But it looks like it's not doing that. But I also don't know what the 5.5 row binary log output for 0 timestamp looks like, and if a parser based on a newer version would read it incorrectly.

I see https://github.com/github/gh-ost/pull/182 was an early fix for timestamps getting time zone conversion.

[druud]

"the problem is a timestamp, which shouldn't have any timezone attached to it" is not how it works.

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

[druud]

https://dev.mysql.com/doc/refman/5.7/en/datetime.html MySQL converts TIMESTAMP values from the current time zone to UTC for storage, and back from UTC to the current time zone for retrieval. (This does not occur for other types such as DATETIME.) By default, the current time zone for each connection is the server's time. [...]

[ggunson]

"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.

[druud]

@ggunson Hi, no apologies needed. To me, a timestamp, because it is stored as a unix-time, has a timezone attached: UTC. But indeed, it doesn't store the active timezone of the session at the time of storage.

I follow now how the special value '0000-00-00 00:00:00' somehow gets converted were it shouldn't. '0000-00-00 00:00:00' is just '0000-00-00 00:00:00', whatever the active timezone of the session. So that indeed is an issue.

https://dev.mysql.com/doc/refman/5.5/en/datetime.html Invalid DATE, DATETIME, or TIMESTAMP values are converted to the “zero” value of the appropriate type ('0000-00-00' or '0000-00-00 00:00:00'). [...] MySQL does not accept TIMESTAMP values that include a zero in the day or month column or values that are not a valid date. The sole exception to this rule is the special “zero” value '0000-00-00 00:00:00'.

[shlomi-noach]

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.

[andreybrokeit]

any new info on this? I have similar issues, trying to add a column to the table where one of the columns have dates in 0000-00-00 00:00:00 format. I am getting an error ERROR Error 1292: Incorrect datetime value: '1970-01-01 00:00:00' for column 'blah'

I understand that 0000 date gets converted to unixtimestamp which turns it into a 1970 but the correct range for timestamp starts at '1970-01-01 00:00:01' and given value is 00:00

[shlomi-noach]

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).

[shlomi-noach]

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.

[shlomi-noach]

https://github.com/github/gh-ost/pull/539 seems to solve the problem. cc @druud @ggunson @andreybrokeit @liuguoshun Can people test on their end? #539 adds this test: https://github.com/github/gh-ost/pull/539/files#diff-78cefd06db5031676f03aa0b708cd02b

[shlomi-noach]

fixed by https://github.com/github/gh-ost/pull/539

[admiral2]

Ca we re-open issue, or I need to create new one?

MySQL version: 10.0.36-MariaDB-0ubuntu0.16.04.1 - Ubuntu 16.04 sql_mode='' system_time_zone='+07'

Issue still present:

2019-03-27 11:48:45 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 07:00:00 +0700 +07 2019-03-27 11:48:44 +0700 +07 2406129 1]

In fix #539 was added for type MYSQL_TYPE_DATETIME but in my case timestamp detected as MYSQL_TYPE_TIMESTAMP so for MYSQL_TYPE_TIMESTAMP also need to add:

case MYSQL_TYPE_TIMESTAMP:
        n = 4
        t := binary.LittleEndian.Uint32(data)
        if t == 0 {
            return "0000-00-00 00:00:00", n, nil
        }
        v = time.Unix(int64(t), 0)

In my case it fixed issue.

[shlomi-noach]

Reopening. Thank you for suggesting a fix.