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

Consume the binlog that doesn't exist in advance

XMLWordPrintable

    • False
    • Hide

      None

      Show
      None
    • False

      Hello, I encountered a problem using debezium MySQL connector to consume MySQL binlog,

      The previous binlog is binlog-004969. The current binlog is binlog-004970,

       
      When binlog-004970 is consumed, an error is reported.

      Note: the error time is 03:33:57 when binlog-004970 is being consumed, but it is found that binlog-004970 was generated at 03:34:5 after verification. Why is this problem encountered?

       

      as follows:

      [2022-05-29 03:33:57,355] ERROR Error during binlog processing. Last offset stored = {transaction_id=null, ts_sec=1653766428, file=mysql-bin.004970, pos=15312364, gtids=a1cb592a-8794-11eb-b8c5-ec0d9ac0106c:1-4516913869, server_id=2841528574, event=1}, binlog reader near position = mysql-bin.004970/15312364 (io.debezium.connector.mysql.MySqlStreamingChangeEventSource:1089)[2022-05-29 03:33:57,357] ERROR Producer failure (io.debezium.pipeline.ErrorHandler:35)io.debezium.DebeziumException: Failed to read next byte from position -116498809 at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1189) at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onCommunicationFailure(MySqlStreamingChangeEventSource.java:1234) at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:980) at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:599) at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:857) at java.lang.Thread.run(Thread.java:748)Caused by: java.io.EOFException: Failed to read next byte from position -116498809 at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:213) at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readInteger(ByteArrayInputStream.java:52) at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:35) at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:27) at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:221) at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:230) at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:952) ... 3 more[2022-05-29 03:33:57,359] INFO Stopped reading binlog after 0 events, last recorded offset: {transaction_id=null, ts_sec=1653766428, file=mysql-bin.004970, pos=15312364, gtids=a1cb592a-8794-11eb-b8c5-ec0d9ac0106c:1-4516913869, server_id=2841528574, event=1} (io.debezium.connector.mysql.MySqlStreamingChangeEventSource:1205)[2022-05-29 03:33:57,395] INFO WorkerSourceTask{id=debezium_job_v7__r-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:398)[2022-05-29 03:33:57,395] INFO WorkerSourceTask{id=debezium_job_v7__r-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:415)[2022-05-29 03:33:57,395] ERROR WorkerSourceTask{id=debezium_job_v7__r-0} Task threw an uncaught and unrecoverable exception (org.apache.kafka.connect.runtime.WorkerTask:177)org.apache.kafka.connect.errors.ConnectException: An exception occurred in the change event producer. This connector will be stopped. at io.debezium.pipeline.ErrorHandler.setProducerThrowable(ErrorHandler.java:50) at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$ReaderThreadLifecycleListener.onCommunicationFailure(MySqlStreamingChangeEventSource.java:1234) at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:980) at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:599) at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:857) at java.lang.Thread.run(Thread.java:748)Caused by: io.debezium.DebeziumException: Failed to read next byte from position -116498809 at io.debezium.connector.mysql.MySqlStreamingChangeEventSource.wrap(MySqlStreamingChangeEventSource.java:1189) ... 5 moreCaused by: java.io.EOFException: Failed to read next byte from position -116498809 at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:213) at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readInteger(ByteArrayInputStream.java:52) at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:35) at com.github.shyiko.mysql.binlog.event.deserialization.EventHeaderV4Deserializer.deserialize(EventHeaderV4Deserializer.java:27) at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:221) at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:230) at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:952) ... 3 more[2022-05-29 03:33:57,395] ERROR WorkerSourceTask{id=debezium_job_v7__r-0} Task is being killed and will not recover until manually restarted (org.apache.kafka.connect.runtime.WorkerTask:178)[2022-05-29 03:33:57,396] INFO Stopping down connector (io.debezium.connector.common.BaseSourceTask:238)[2022-05-29 03:33:57,468] INFO Finished streaming (io.debezium.pipeline.ChangeEventSourceCoordinator:175)[2022-05-29 03:33:57,475] ERROR Exception while closing JDBC connection (io.debezium.connector.mysql.MySqlConnectorTask:230)java.sql.SQLNonTransientConnectionException: Communications link failure during rollback(). Transaction resolution unknown. at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1838) at com.mysql.cj.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:1695) at com.mysql.cj.jdbc.ConnectionImpl.close(ConnectionImpl.java:714) at io.debezium.jdbc.JdbcConnection.lambda$doClose$3(JdbcConnection.java:955) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)[2022-05-29 03:33:57,476] INFO [Producer clientId=-dbhistory] Closing the Kafka producer with timeoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer:1145)[2022-05-29 03:33:57,478] INFO [Producer clientId=producer-4] Closing the Kafka producer with timeoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer:1145)[2022-05-29 03:34:00,035] INFO WorkerSourceTask{id=debezium_job_v7__r-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:398)[2022-05-29 03:34:00,035] INFO WorkerSourceTask{id=debezium_job_v7__r-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:415)[2022-05-29 03:34:10,036] INFO WorkerSourceTask{id=debezium_job_v7__r-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:398) 

       
       
      In addition, debezium continues to execute normally. The log is

       info workersourcetask{id=debezium_job_v7__r-0} committing offsets (org.apache.kafka.connect.runtime.workersourcetask:398), 

      but Kafka is not written

              Unassigned Unassigned
              ogrea C Lin (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: