-
Bug
-
Resolution: Done
-
Major
-
None
-
None
-
False
-
None
-
False
io.debezium.connector.mysql.IncrementalSnapshotIT#schemaChanges fails randomly (in CI quite ofter) with:
2022-05-13T14:01:01.8185328Z 2022-05-13 14:01:01,753 ERROR MySQL|is_test||binlog| Error during binlog processing. Last offset stored = {transaction_id=null, ts_sec=1652450461, file=mysql-bin.000002, pos=1513406, incremental_snapshot_maximum_key=aced0005757200135b4c6a6176612e6c616e672e4f626a6563743b90ce589f1073296c020000787000000001737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b0200007870000003e8, server_id=112233, event=2, incremental_snapshot_collections=incremental_snapshot-test_fvgezg.a, incremental_snapshot_primary_key=aced0005757200135b4c6a6176612e6c616e672e4f626a6563743b90ce589f1073296c020000787000000001737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000014}, binlog reader near position = mysql-bin.000002/1513669 [io.debezium.connector.mysql.MySqlStreamingChangeEventSource] 2022-05-13T14:01:01.8187527Z 2022-05-13 14:01:01,755 ERROR MySQL|is_test||binlog| Producer failure [io.debezium.pipeline.ErrorHandler] 2022-05-13T14:01:01.8188105Z io.debezium.DebeziumException: Error processing binlog event 2022-05-13T14:01:01.8188852Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.handleEvent(MySqlStreamingChangeEventSource.java:370) 2022-05-13T14:01:01.8189693Z at io.debezium.connector.mysql.EventBuffer.completeTransaction(EventBuffer.java:201) 2022-05-13T14:01:01.8190344Z at io.debezium.connector.mysql.EventBuffer.add(EventBuffer.java:110) 2022-05-13T14:01:01.8191103Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.lambda$execute$26(MySqlStreamingChangeEventSource.java:875) 2022-05-13T14:01:01.8191972Z at com.github.shyiko.mysql.binlog.BinaryLogClient.notifyEventListeners(BinaryLogClient.java:1125) 2022-05-13T14:01:01.8192786Z at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:973) 2022-05-13T14:01:01.8193538Z at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:599) 2022-05-13T14:01:01.8194200Z at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:857) 2022-05-13T14:01:01.8194745Z at java.base/java.lang.Thread.run(Thread.java:833) 2022-05-13T14:01:01.8197530Z Caused by: org.apache.kafka.connect.errors.ConnectException: Error while processing event at offset {transaction_id=null, ts_sec=1652450461, file=mysql-bin.000002, pos=1513406, incremental_snapshot_maximum_key=aced0005757200135b4c6a6176612e6c616e672e4f626a6563743b90ce589f1073296c020000787000000001737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b0200007870000003e8, row=1, server_id=112233, event=2, incremental_snapshot_collections=incremental_snapshot-test_fvgezg.a, incremental_snapshot_primary_key=aced0005757200135b4c6a6176612e6c616e672e4f626a6563743b90ce589f1073296c020000787000000001737200116a6176612e6c616e672e496e746567657212e2a0a4f781873802000149000576616c7565787200106a6176612e6c616e672e4e756d62657286ac951d0b94e08b020000787000000014} 2022-05-13T14:01:01.8199567Z at io.debezium.pipeline.EventDispatcher.dispatchDataChangeEvent(EventDispatcher.java:254) 2022-05-13T14:01:01.8200436Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.lambda$handleInsert$4(MySqlStreamingChangeEventSource.java:701) 2022-05-13T14:01:01.8201393Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.handleChange(MySqlStreamingChangeEventSource.java:759) 2022-05-13T14:01:01.8202349Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.handleInsert(MySqlStreamingChangeEventSource.java:699) 2022-05-13T14:01:01.8203362Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.lambda$execute$16(MySqlStreamingChangeEventSource.java:847) 2022-05-13T14:01:01.8204299Z at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.handleEvent(MySqlStreamingChangeEventSource.java:350) 2022-05-13T14:01:01.8204953Z ... 8 common frames omitted 2022-05-13T14:01:01.8205614Z Caused by: io.debezium.DebeziumException: Snapshotting of table incremental_snapshot-test_fvgezg.a failed 2022-05-13T14:01:01.8206665Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.readSchema(AbstractIncrementalSnapshotChangeEventSource.java:398) 2022-05-13T14:01:01.8208180Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.verifySchemaUnchanged(AbstractIncrementalSnapshotChangeEventSource.java:382) 2022-05-13T14:01:01.8209960Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.schemaHistoryIsUpToDate(AbstractIncrementalSnapshotChangeEventSource.java:374) 2022-05-13T14:01:01.8211480Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.readChunk(AbstractIncrementalSnapshotChangeEventSource.java:286) 2022-05-13T14:01:01.8212915Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.closeWindow(AbstractIncrementalSnapshotChangeEventSource.java:100) 2022-05-13T14:01:01.8214203Z at io.debezium.pipeline.source.snapshot.incremental.CloseIncrementalSnapshotWindow.arrived(CloseIncrementalSnapshotWindow.java:32) 2022-05-13T14:01:01.8215044Z at io.debezium.pipeline.signal.Signal.process(Signal.java:135) 2022-05-13T14:01:01.8215608Z at io.debezium.pipeline.signal.Signal.process(Signal.java:173) 2022-05-13T14:01:01.8216193Z at io.debezium.pipeline.EventDispatcher$2.changeRecord(EventDispatcher.java:228) 2022-05-13T14:01:01.8216978Z at io.debezium.relational.RelationalChangeRecordEmitter.emitCreateRecord(RelationalChangeRecordEmitter.java:79) 2022-05-13T14:01:01.8217909Z at io.debezium.relational.RelationalChangeRecordEmitter.emitChangeRecords(RelationalChangeRecordEmitter.java:47) 2022-05-13T14:01:01.8218755Z at io.debezium.pipeline.EventDispatcher.dispatchDataChangeEvent(EventDispatcher.java:217) 2022-05-13T14:01:01.8219306Z ... 13 common frames omitted 2022-05-13T14:01:01.8219847Z Caused by: java.sql.SQLException: java.lang.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2 2022-05-13T14:01:01.8220524Z at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129) 2022-05-13T14:01:01.8221203Z at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) 2022-05-13T14:01:01.8221867Z at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) 2022-05-13T14:01:01.8222518Z at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) 2022-05-13T14:01:01.8223170Z at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) 2022-05-13T14:01:01.8223880Z at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:440) 2022-05-13T14:01:01.8224641Z at com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1009) 2022-05-13T14:01:01.8225776Z at io.debezium.pipeline.source.snapshot.incremental.AbstractIncrementalSnapshotChangeEventSource.readSchema(AbstractIncrementalSnapshotChangeEventSource.java:394) 2022-05-13T14:01:01.8226647Z ... 24 common frames omitted 2022-05-13T14:01:01.8227084Z Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 2 out of bounds for length 2 2022-05-13T14:01:01.8227755Z at com.mysql.cj.protocol.a.MergingColumnDefinitionFactory.createFromFields(MergingColumnDefinitionFactory.java:61) 2022-05-13T14:01:01.8228466Z at com.mysql.cj.protocol.a.ColumnDefinitionReader.read(ColumnDefinitionReader.java:80) 2022-05-13T14:01:01.8229085Z at com.mysql.cj.protocol.a.ColumnDefinitionReader.read(ColumnDefinitionReader.java:40) 2022-05-13T14:01:01.8229723Z at com.mysql.cj.protocol.a.NativeProtocol.read(NativeProtocol.java:1587) 2022-05-13T14:01:01.8230294Z at com.mysql.cj.protocol.a.BinaryResultsetReader.read(BinaryResultsetReader.java:70) 2022-05-13T14:01:01.8230896Z at com.mysql.cj.protocol.a.BinaryResultsetReader.read(BinaryResultsetReader.java:50) 2022-05-13T14:01:01.8231465Z at com.mysql.cj.protocol.a.NativeProtocol.read(NativeProtocol.java:1600) 2022-05-13T14:01:01.8232029Z at com.mysql.cj.protocol.a.NativeProtocol.readAllResults(NativeProtocol.java:1654) 2022-05-13T14:01:01.8232632Z at com.mysql.cj.ServerPreparedQuery.readExecuteResult(ServerPreparedQuery.java:433) 2022-05-13T14:01:01.8233213Z at com.mysql.cj.ServerPreparedQuery.serverExecute(ServerPreparedQuery.java:211) 2022-05-13T14:01:01.8234623Z at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:631) 2022-05-13T14:01:01.8235419Z at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:417) 2022-05-13T14:01:01.8235924Z ... 26 common frames omitted