-
Bug
-
Resolution: Done
-
Major
-
None
-
None
-
False
-
-
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