Uploaded image for project: 'Debezium'
  1. Debezium
  2. DBZ-5131

Test IncrementalSnapshotIT##schemaChanges fails randomly

XMLWordPrintable

    • 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
      

              vjuranek@redhat.com Vojtech Juranek
              vjuranek@redhat.com Vojtech Juranek
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: