A 0 valued DATETIME causes a ClassCastException at apply time on slaves using row binlogs.

GoogleCodeExporter commented 9 years ago

What steps will reproduce the problem?

1. Use row based bin logging.
2. Update a row that has a '0000-00-00 00:00:00' datetime column, OR
    Update a row and set a timestamp column to '0000-00-00 00:00:00'

What is the expected output?
Successful replication
...

What do you see instead?
INFO   | jvm 1    | 2013/08/22 15:56:15 | java.lang.ClassCastException: 
java.lang.Integer cannot be cast to java.sql.Timestamp
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.MySQLDrizzleApplier.setObject(MySQLDr
izzleApplier.java:342)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.bindColumnValues(JdbcAppl
ier.java:540)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.applyOneRowChangePrepared
(JdbcApplier.java:1005)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.applyRowChangeData(JdbcAp
plier.java:1234)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.JdbcApplier.apply(JdbcApplier.java:13
27)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.applier.ApplierWrapper.apply(ApplierWrapper.j
ava:101)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.apply(SingleTh
readStageTask.java:706)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.runTask(Single
ThreadStageTask.java:484)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.run(SingleThre
adStageTask.java:169)
INFO   | jvm 1    | 2013/08/22 15:56:15 |       at 
java.lang.Thread.run(Thread.java:724)

...

What version of the product are you using?
tungsten-replicator-2.1.1-230
...

On what operating system?
CentOS 6.2
Java(TM) SE Runtime Environment (build 1.7.0_25-b15)
...

Please provide any additional information below.

Notes:

This has only been a problem since updating to 2.1.1

...

Original issue reported on code.google.com by bran...@seibelnet.ca on 22 Aug 2013 at 8:50

Blocked on: #381

GoogleCodeExporter commented 9 years ago

Oop should note MySQL version is Percona 5.5.31-rel30.3.520

Original comment by bran...@seibelnet.ca on 22 Aug 2013 at 8:54

GoogleCodeExporter commented 9 years ago

Thanks for your report!

This is possibly a regression of Issue#381

How to reproduce:

use test;
drop table if exists test_datetime;
drop table if exists test_timestamp;
create table test_datetime(id int not null primary key, dt datetime);
create table test_timestamp(id int not null primary key, ts timestamp);

set binlog_format=statement;
insert into test_datetime values (1,  '0000-00-00 00:00:00' );
insert into test_timestamp values (1,  '0000-00-00 00:00:00' );

set binlog_format=row;

insert into test_datetime values (2,  '0000-00-00 00:00:00' );
insert into test_timestamp values (2,  '0000-00-00 00:00:00' );

select * from test_datetime;
select * from test_timestamp;

Original comment by g.maxia on 22 Aug 2013 at 9:29

Changed state: Accepted
Added labels: FixedIn-2.1.2, FoundIn-2.1.2, Priority-Critical, Publish-Release-Note
Removed labels: FoundIn, Priority-Medium

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 23 Aug 2013 at 10:06

Now blocked on: #381

GoogleCodeExporter commented 9 years ago

First clues (need more investigation):

the RowsLogEvent changes done by the r1508 backport *didn't* overwrite the 
logic that has been added to address the Issue 381 previously. In fact, the new 
MySQL 5.6 binary log field types MysqlBinlog.MYSQL_TYPE_TIMESTAMP2 and 
MYSQL_TYPE_DATE2 has that zero-handling logic too.

The exception itself is a bit different from Issue 381.

Previous exception: SQLDataException: Incorrect datetime value: '1969-12-31 
16:00:00' for column 'myTimeStamp' at row 1
Current exception: Integer cannot be cast to java.sql.Timestamp

While the code that handles zero-dates looks like this is still in-place:

637     if (i32 == 0)       
638     {
639     value.setValue(Integer.valueOf(0));
640     }

Conclusion: the fix of Issue 381 is there, but the zero integer can't be 
applied in this case. We need to find the reason why.

Original comment by linas.vi...@continuent.com on 23 Aug 2013 at 10:22

Added labels: FoundIn-2.1.1
Removed labels: FoundIn-2.1.2

GoogleCodeExporter commented 9 years ago

The failure occurs regardless of the MySQL version (tested with 5.1, 5.5, and 
5.6).

The same failure happens for both DATETIME and TIMESTAMP

Original comment by g.maxia on 23 Aug 2013 at 10:36

GoogleCodeExporter commented 9 years ago

A one-liner fix is provided in r1616. Needs QA verification.

Original comment by linas.vi...@continuent.com on 23 Aug 2013 at 1:44

Changed state: QA

GoogleCodeExporter commented 9 years ago

After this fix, the extractor fails.
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,980 [cookbook - 
binlog-to-q-0] INFO  pipeline.SingleThreadStageTask Last successfully processed 
event prior to termination: seqno=6 eventid=mysql-bin.000002:0000000000001600;0
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,981 [cookbook - 
binlog-to-q-0] INFO  pipeline.SingleThreadStageTask Task event count: 7
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,981 [cookbook - 
pool-2-thread-1] ERROR management.OpenReplicatorManager Received error 
notification, shutting down services :
INFO   | jvm 1    | 2013/08/24 09:36:37 | Event extraction failed
INFO   | jvm 1    | 2013/08/24 09:36:37 | 
com.continuent.tungsten.replicator.extractor.ExtractorException: Unexpected 
failure while extracting event mysql-bin.000002 (1810)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.MySQLExtractor.extractEvent(M
ySQLExtractor.java:1062)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.MySQLExtractor.extract(MySQLE
xtractor.java:1086)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.ExtractorWrapper.extract(ExtractorW
rapper.java:96)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.ExtractorWrapper.extract(ExtractorW
rapper.java:56)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.runTask(Single
ThreadStageTask.java:238)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.pipeline.SingleThreadStageTask.run(SingleThre
adStageTask.java:169)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
java.lang.Thread.run(Thread.java:724)
INFO   | jvm 1    | 2013/08/24 09:36:37 | Caused by: 
java.lang.ArrayIndexOutOfBoundsException: 43
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.conversion.BigEndianConversio
n.convertNBytesToLong(BigEndianConversion.java:111)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.RowsLogEvent.extractValue(Row
sLogEvent.java:628)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.RowsLogEvent.processExtracted
EventRow(RowsLogEvent.java:1202)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.WriteRowsLogEvent.processExtr
actedEvent(WriteRowsLogEvent.java:88)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       at 
com.continuent.tungsten.replicator.extractor.mysql.MySQLExtractor.extractEvent(M
ySQLExtractor.java:897)
INFO   | jvm 1    | 2013/08/24 09:36:37 |       ... 6 more
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,984 [cookbook - 
pool-2-thread-1] WARN  management.OpenReplicatorManager Performing emergency 
service shutdown
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,984 [cookbook - 
pool-2-thread-1] INFO  pipeline.Pipeline Shutting down pipeline: master
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,984 [cookbook - 
q-to-thl-0] WARN  pipeline.SingleThreadStageTask Received unexpected interrupt 
in stage task: q-to-thl
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,985 [cookbook - 
q-to-thl-0] INFO  pipeline.SingleThreadStageTask Terminating processing for 
stage task thread
INFO   | jvm 1    | 2013/08/24 09:36:37 | 2013-08-24 09:36:36,985 [cookbook - 
q-to-thl-0] INFO  pipeline.SingleThreadStageTask Last successfully processed 
event prior to termination: seqno=6 eventid=mysql-bin.000002:0000000000001600;0

how to reproduce:

use test;
drop table if exists boundaries;

create table boundaries(id int not null primary key, c char(20),
    ti time,
    d date,
    dt datetime,
    ts timestamp
) engine=innodb;

set binlog_format=row;

insert into boundaries values (1, 'all valid', '10:10:10', '2013-08-24', 
'2013-08-24 10:10:10', '2013-08-24 10:10:10');
insert into boundaries values (2, 'zero time', '00:00:00', '2013-08-24', 
'2013-08-24 10:10:10', '2013-08-24 10:10:10');
insert into boundaries values (3, 'zero date', '10:10:10', '0000-00-00', 
'2013-08-24 10:10:10', '2013-08-24 10:10:10');
insert into boundaries values (4, 'zero datetime', '10:10:10', '2013-08-24', 
'0000-00-00 00:00:00', '2013-08-24 10:10:10');  ## extractor breaks here
insert into boundaries values (5, 'zero timestamp', '10:10:10', '2013-08-24', 
'2013-08-24 10:10:10', '0000-00-00 00:00:00');

Original comment by g.maxia on 24 Aug 2013 at 8:38

Changed state: Started

GoogleCodeExporter commented 9 years ago

This issue should be fixed now.

Original comment by stephane...@continuent.com on 24 Aug 2013 at 11:21

GoogleCodeExporter commented 9 years ago

Original comment by linas.vi...@continuent.com on 25 Aug 2013 at 7:41

Changed state: QA

GoogleCodeExporter commented 9 years ago

This issue is fixed. Build 2.1.2-23 passes the test

Original comment by g.maxia on 26 Aug 2013 at 6:26

Changed state: Documenting

GoogleCodeExporter commented 9 years ago

An entry has been added to the release notes for 2.1.2.

Original comment by mc.br...@continuent.com on 28 Aug 2013 at 11:32

Changed state: Fixed

GoogleCodeExporter commented 9 years ago

Thanks for the quick turn around on this guys!

Original comment by bran...@seibelnet.ca on 28 Aug 2013 at 11:57

bigcy / tungsten-replicator

A 0 valued DATETIME causes a ClassCastException at apply time on slaves using row binlogs. #679