Bug #71035 mysqlbinlog dumps out improperly-formatted TIMESTAMP values
Submitted: 28 Nov 2013 15:53 Modified: 30 Nov 2013 22:32
Reporter: Guy Paddock Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S2 (Serious)
Version:mysqlbinlog Ver 3.4, 5.1.74, 5.5.35, 5.6.16 OS:Linux (CentOS release 6.4 2.6.32-358.23.2.el6.x86_64)
Assigned to: CPU Architecture:Any
Tags: bugs, mysqlbinlog, timestamp

[28 Nov 2013 15:53] Guy Paddock
Description:
On a test VM, we are evaluating MySQL Flexviews on CentOS 6.4, running MySQL Community Edition 5.6.14, which was provided through the official MySQL yum repositories.

On urging from Justin Swanhart, the author of Flexviews, we're using the version of mysqlbinlog from 5.7 that has the patch for DECIMAL fields. This version of mysqlbinlog reports its tool version as 3.4.

Anyway, it looks like mysqlbinlog doesn't properly format values for TIMESTAMP fields. The output appears to be formatting them in UNIX timestamp format when the correct format should be "YYYY-MM-DD HH:MM:SS" format.

How to repeat:
1. Enable binary logging in ROW format.
2. Create this sample table in a database:

CREATE TABLE `mview_signal` (
  `signal_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `signal_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`signal_id`),
  UNIQUE KEY `signal_id` (`signal_id`)
) ENGINE=InnoDB AUTO_INCREMENT=27 DEFAULT CHARSET=utf8

3. Run this insert statement:
INSERT INTO mview_signal VALUES (100, '2013-11-28 00:20:34');

4. Use mysqlbinlog to dump the transaction:
mysqlbinlog --user=<USERNAME> --host=<HOST> --port=<PORT> --password=<PASSWORD> --base64-output=decode-rows -v -R --start-position=<START POS> --stop-position=<STOP POS> <LATEST BINLOG FILE>

It's expected to see this:
#131128  0:20:34 server id 1  end_log_pos 12833226 CRC32 0xe9264176     Query   thread_id=326   exec_time=0     error_code=0
SET TIMESTAMP=1385616034/*!*/;
BEGIN
/*!*/;
# at 12833226
#131128  0:20:34 server id 1  end_log_pos 12833288 CRC32 0xdeb83538     Table_map: `flexviews`.`mview_signal` mapped to number 89
# at 12833288
#131128  0:20:34 server id 1  end_log_pos 12833336 CRC32 0xb997459a     Write_rows: table id 89 flags: STMT_END_F
### INSERT INTO `flexviews`.`mview_signal`
### SET
###   @1=100
###   @2='2013-11-28 00:20:34'
# at 12833336
#131128  0:20:34 server id 1  end_log_pos 12833367 CRC32 0x150a5278     Xid = 336989
COMMIT/*!*/;

We actually see this:
#131128  0:20:34 server id 1  end_log_pos 12833226 CRC32 0xe9264176     Query   thread_id=326   exec_time=0     error_code=0
SET TIMESTAMP=1385616034/*!*/;
BEGIN
/*!*/;
# at 12833226
#131128  0:20:34 server id 1  end_log_pos 12833288 CRC32 0xdeb83538     Table_map: `flexviews`.`mview_signal` mapped to number 89
# at 12833288
#131128  0:20:34 server id 1  end_log_pos 12833336 CRC32 0xb997459a     Write_rows: table id 89 flags: STMT_END_F
### INSERT INTO `flexviews`.`mview_signal`
### SET
###   @1=100
###   @2=1385616034
# at 12833336
#131128  0:20:34 server id 1  end_log_pos 12833367 CRC32 0x150a5278     Xid = 336989
COMMIT/*!*/;

Suggested fix:
It looks like the error might be in sql/log_event.cc, in log_event_print_value(), somewhere in this piece:

  case MYSQL_TYPE_TIMESTAMP:
    {
      uint32 i32= uint4korr(ptr);
      my_b_printf(file, "%d", i32);
      my_snprintf(typestr, typestr_length, "TIMESTAMP");
      return 4;
    }

  case MYSQL_TYPE_TIMESTAMP2:
    {
      char buf[MAX_DATE_STRING_REP_LENGTH];
      struct timeval tm;
      my_timestamp_from_binary(&tm, ptr, meta);
      int buflen= my_timeval_to_str(&tm, buf, meta);
      my_b_write(file, buf, buflen);
      my_snprintf(typestr, typestr_length, "TIMESTAMP(%d)", meta);
      return my_timestamp_binary_length(meta);
    }

If I'm not mistaken, this just dumps the value of the timestamp as an integer (%d).

Shouldn't this be more like the handling of MYSQL_TYPE_DATETIME?

  case MYSQL_TYPE_DATETIME:
    {
      size_t d, t;
      uint64 i64= uint8korr(ptr); /* YYYYMMDDhhmmss */
      d= i64 / 1000000;
      t= i64 % 1000000;
      my_b_printf(file, "%04d-%02d-%02d %02d:%02d:%02d",
                  static_cast<int>(d / 10000),
                  static_cast<int>(d % 10000) / 100,
                  static_cast<int>(d % 100),
                  static_cast<int>(t / 10000),
                  static_cast<int>(t % 10000) / 100,
                  static_cast<int>(t % 100));
      my_snprintf(typestr, typestr_length, "DATETIME");
      return 8;
    }
[28 Nov 2013 18:09] Sveta Smirnova
Thank you for the report.

Verified as described. Not sure if we should consider this a s a bug though.
[30 Nov 2013 22:32] Guy Paddock
How is this not considered a bug? It affects user's ability to replay SQL from the binary log.
[1 Dec 2013 8:38] Hartmut Holzgraefe
Not a bug as the -v comments are not supposed to be real, replayable SQL statements anyway:

    -v, --verbose       Reconstruct pseudo-SQL statements out of row events.

So while it would be nice to have a more human readable form of output here this only qualifies as a feature request.

If you really want to convert the -v generated pseudo-SQL into actual working SQL statements you'd need to put in quite a bit of parsing and post processing effort anyway, and having to convert raw timestamp values by e.g. wrapping them in FROM_UNIXTIME() calls looks like a rather minor issue with that ...
[30 Oct 2014 7:05] ukits Byun
I'm sure that this is a bug.

On replication,

the timestamp column on WHERE cluase in DELETE or UPDATE use unix_timestamp format.
the slave cannot find matched row.

for example,

binlog:

DELETE FROM `db`.`table` WHERE
 @1 = 'xxx'
 @2 = 'yyy'
 @3 = 1414491155      // this is timestamp formatted column

and @3 column on slave has value '2014-10-28 19:12:35';
as you know, timestamp '1414491155' is date '2014-10-28 19:12:35'

the query CANNOT find rows on slave.
an error occured,

mysql> show slave status\G
*************************** 1. row ***************************
...
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1032
                   Last_Error: Could not execute Delete_rows event on table db.table; Can't find record in 'table', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.000021, end_log_pos 39357456

MySQL v5.6.21
[30 Oct 2014 8:47] Hartmut Holzgraefe
Hello ukits,

what you're experiencing might actually be a completely different problem, so allow me to ask for the timezone settings on your master and slave.

If they both use SYSTEM timezone (the default) and master and slave operating systems are set to different timezones you may actually run into problems due to this. If that is the case the solution would be to explicitly set the timezone within mysql to the actual time zone instead of SYSTEM so that mysqld knows what conversions to apply. When a slave sees that master and slave time zone are the same it just assumes that no conversion is necessary, even in the case of SYSTEM, as it doesn't really know anything about the underlying system time zone ...