Loading...

XML

Word

Printable

Details

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 0.4.1
Affects Version/s: 0.4
Component/s: mysql-connector
Labels:
None

Git Pull Request:
https://github.com/debezium/debezium/pull/201

SFDC Cases Counter:
SFDC Cases Links:

Description

I'm getting an ArrayIndexOutOfBoundsException error in the MySqlValueConverters::convertEnumToString method. I've spent hours trying to recreate it in a simple environment, but it seems to happen randomly, meaning that the same sql queries sometime succeed, and sometimes create this error. I've not been able to repeatedly replicate it, but it happens after 3-4 update queries, usually, at what point debezium crashes and stops propagating updates to kafka.

Mysql version:

mysql  Ver 14.14 Distrib 5.6.32, for debian-linux-gnu (x86_64)

The error:

Feb 24 21:12:23 devbox debezium-mysql-start.sh[3283]: [2017-02-24 21:12:23,531] INFO Finished WorkerSourceTask{id=cep_debezium_mysql-0} commitOffsets successfully in 6 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:356)
Feb 24 21:13:22 devbox debezium-mysql-start.sh[3283]: [2017-02-24 21:13:22,635] INFO 1 records sent during previous 00:01:05.701, last recorded offset: {ts_sec=1487970801, file=mysql-bin.000001, pos=2143, row=1, server_id=1, event=2} (io.debezium.connector.mysql.BinlogReader:267)
Feb 24 21:13:23 devbox debezium-mysql-start.sh[3283]: [2017-02-24 21:13:23,535] INFO Finished WorkerSourceTask{id=cep_debezium_mysql-0} commitOffsets successfully in 1 ms (org.apache.kafka.connect.runtime.WorkerSourceTask:356)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]: [2017-02-24 21:14:38,036] ERROR Failed due to error: Error processing binlog event (io.debezium.connector.mysql.BinlogReader:143)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]: org.apache.kafka.connect.errors.ConnectException: -1
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.AbstractReader.wrap(AbstractReader.java:164)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.AbstractReader.failed(AbstractReader.java:142)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:326)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at com.github.shyiko.mysql.binlog.BinaryLogClient.notifyEventListeners(BinaryLogClient.java:902)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:760)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:472)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at com.github.shyiko.mysql.binlog.BinaryLogClient$5.run(BinaryLogClient.java:657)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at java.lang.Thread.run(Thread.java:745)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]: Caused by: java.lang.ArrayIndexOutOfBoundsException: -1
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at java.util.ArrayList.elementData(ArrayList.java:418)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at java.util.ArrayList.get(ArrayList.java:431)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.MySqlValueConverters.convertEnumToString(MySqlValueConverters.java:311)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.MySqlValueConverters.lambda$converter$2(MySqlValueConverters.java:125)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.relational.TableSchemaBuilder.lambda$createValueGenerator$3(TableSchemaBuilder.java:230)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.relational.TableSchema.valueFromColumnData(TableSchema.java:111)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.RecordMakers$1.update(RecordMakers.java:235)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.RecordMakers$RecordsForTable.update(RecordMakers.java:444)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.BinlogReader.handleUpdate(BinlogReader.java:551)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         at io.debezium.connector.mysql.BinlogReader.handleEvent(BinlogReader.java:313)
Feb 24 21:14:38 devbox debezium-mysql-start.sh[3283]:         ... 5 more

DDL:

Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]: [2017-02-24 21:12:16,551] INFO         CREATE TABLE `conversation` (
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `id` int(11) NOT NULL AUTO_INCREMENT,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `data_source` enum('twitter','facebook','generic') DEFAULT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `owner_profile_id` bigint(20) unsigned NOT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `participant_profile_id` bigint(20) unsigned NOT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `status` enum('new','archived','assigned','bulkarchiving','pending') DEFAULT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `not_archived_since` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `not_assigned_since` timestamp NULL DEFAULT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `last_message_received` timestamp NULL DEFAULT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `status_updated_at` timestamp NULL DEFAULT NULL,
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `assigned_to_client_user_id` int(11) NOT NULL DEFAULT '0',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `last_updated_at` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `inverted_vip` tinyint(3) unsigned NOT NULL DEFAULT '1',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `inverted_followers_count` int(11) NOT NULL DEFAULT '0',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `inverted_not_archived_since` int(10) unsigned NOT NULL DEFAULT '0',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `inverted_status_updated_at` int(10) unsigned DEFAULT '0',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   `batch_id` int(11) NOT NULL DEFAULT '0',
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   PRIMARY KEY (`id`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   UNIQUE KEY `owner_participant` (`data_source`,`owner_profile_id`,`participant_profile_id`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `status_source_vip` (`status`,`data_source`,`inverted_vip`,`status_updated_at`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `status_source_vip_inverted` (`status`,`data_source`,`inverted_vip`,`inverted_status_updated_at`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `status_source_vip_inverted_followers` (`status`,`data_source`,`inverted_vip`,`inverted_followers_count`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `status_source_inverted_updated` (`status`,`data_source`,`inverted_status_updated_at`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `status_source_updated` (`status`,`data_source`,`status_updated_at`),
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]:   KEY `batch_id` (`batch_id`)
Feb 24 21:12:16 devbox debezium-mysql-start.sh[3283]: ) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8 (io.debezium.connector.mysql.SnapshotReader:697)

The binlog entry/query that fails:

UPDATE `conversation` SET `assigned_to_client_user_id` = NULL, `status` = 'archived', `not_archived_since` = '2017-02-24 21:14:37', `inverted_not_archived_since` = TIMESTAMPDIFF(SECOND, '2017-02-24 21:14:37', '2050-01-01'), `status_updated_at` = '2017-02-24 21:14:37', `inverted_status_updated_at` = TIMESTAMPDIFF(SECOND, '2017-02-24 21:14:37', '2050-01-01'   ) WHERE `id` = '2'

BINLOG '
PaKwWBMBAAAAYQAAABgPAAAAAEgAAAAAAAMAFWxvY2FsX3R3ZWV0c19jbGllbnRfMQAMY29udmVy
c2F0aW9uABAD/ggI/hEREREDEQEDAwMDCfcB9wEAAAAAANJBGLZ9bg==
PaKwWB8BAAAAmAAAALAPAAAAAEgAAAAAAAEAAgAQ/////8AAAgAAAAEGREmkAAAAAMSrEqQAAAAA
AViwoCtYsKHxAAAAAFiwnskB/////9XVyT3V1ck9AAAAAMAAAgAAAAEGREmkAAAAAMSrEqQAAAAA
Aliwoj1YsKI9AAAAAFiwnskB/////8PTyT3D08k9AAAAAK9hASc=
'/*!*/;
### UPDATE `local_tweets_client_1`.`conversation`
### WHERE
###   @1=2
###   @2=1
###   @3=2756264966
###   @4=2752687044
###   @5=1
###   @6=1487970347
###   @7=NULL
###   @8=NULL
###   @9=1487970801
###   @10=0
###   @11=1487969993
###   @12=1
###   @13=-1 (4294967295)
###   @14=1036637653
###   @15=1036637653
###   @16=0
### SET
###   @1=2
###   @2=1
###   @3=2756264966
###   @4=2752687044
###   @5=2
###   @6=1487970877
###   @7=NULL
###   @8=NULL
###   @9=1487970877
###   @10=0
###   @11=1487969993
###   @12=1
###   @13=-1 (4294967295)
###   @14=1036637123
###   @15=1036637123
###   @16=0

A previous, similar binlog entry that works, updating the same enum, from this sql:

UPDATE `conversation` SET `status` = 'pending', `status_updated_at` = '2017-02-24 21:10:45' WHERE `id` = '2'

BINLOG '
8aGwWBMBAAAAYQAAACMJAAAAAEgAAAAAAAMAFWxvY2FsX3R3ZWV0c19jbGllbnRfMQAMY29udmVy
c2F0aW9uABAD/ggI/hEREREDEQEDAwMDCfcB9wEAAAAAANJBgui9Ow==
8aGwWB8BAAAAmAAAALsJAAAAAEgAAAAAAAEAAgAQ/////8AAAgAAAAEGREmkAAAAAMSrEqQAAAAA
BViwoCtYsKFVAAAAAFiwnskB/////9XVyT3V1ck9AAAAAMAAAgAAAAEGREmkAAAAAMSrEqQAAAAA
AViwoCtYsKHxAAAAAFiwnskB/////9XVyT3V1ck9AAAAABM9xJI=
'/*!*/;
### UPDATE `local_tweets_client_1`.`conversation`
### WHERE
###   @1=2
###   @2=1
###   @3=2756264966
###   @4=2752687044
###   @5=5
###   @6=1487970347
###   @7=NULL
###   @8=NULL
###   @9=1487970645
###   @10=0
###   @11=1487969993
###   @12=1
###   @13=-1 (4294967295)
###   @14=1036637653
###   @15=1036637653
###   @16=0
### SET
###   @1=2
###   @2=1
###   @3=2756264966
###   @4=2752687044
###   @5=1
###   @6=1487970347
###   @7=NULL
###   @8=NULL
###   @9=1487970801
###   @10=0
###   @11=1487969993
###   @12=1
###   @13=-1 (4294967295)
###   @14=1036637653
###   @15=1036637653
###   @16=0

Attachments

Activity

People

Assignee:: Randall Hauch (Inactive)

Reporter:: Johan Genberg (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2017/02/24 4:30 PM

Updated:: 2017/08/17 9:07 AM

Resolved:: 2017/03/16 3:16 PM