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

Unhandled exception prevents snapshot.mode : when_needed functioning

    Details

    • Steps to Reproduce:
      Hide
      • Setup the connector and successfully initialise.
      • Stop the connector and leave stopped until the last binlog entry has been purged
      • Restart the connector with `snapshot.mode` set to `when_needed`
      Show
      Setup the connector and successfully initialise. Stop the connector and leave stopped until the last binlog entry has been purged Restart the connector with `snapshot.mode` set to `when_needed`

      Description

      When restarting a mysql connector that has been stopped for long enough for the binlog entries to be purged, it becomes impossible to restart or recover the connector.

      [2019-04-18 17:58:21,882] INFO MySQL current GTID set 5e58cadb-e65a-11e8-98d7-42010a94003b:1-13564344 does contain the GTID set required by the connector 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 (io.debezium.connector.mysql.MySqlConnectorTask:493)
      [2019-04-18 17:58:21,886] INFO Requested thread factory for connector MySqlConnector, id = passkit-io-dev named = binlog-client (io.debezium.util.Threads:250)
      [2019-04-18 17:58:21,892] INFO GTID set purged on server: 5e58cadb-e65a-11e8-98d7-42010a94003b:1-12728623 (io.debezium.connector.mysql.BinlogReader:326)
      [2019-04-18 17:58:21,892] INFO Attempting to generate a filtered GTID set (io.debezium.connector.mysql.MySqlTaskContext:306)
      [2019-04-18 17:58:21,892] INFO GTID set from previous recorded offset: 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 (io.debezium.connector.mysql.MySqlTaskContext:307)
      [2019-04-18 17:58:21,892] INFO GTID set available on server: 5e58cadb-e65a-11e8-98d7-42010a94003b:1-13564344 (io.debezium.connector.mysql.MySqlTaskContext:314)
      [2019-04-18 17:58:21,892] INFO Final merged GTID set to use when connecting to MySQL: 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 (io.debezium.connector.mysql.MySqlTaskContext:335)
      [2019-04-18 17:58:21,892] INFO Registering binlog reader with GTID set: 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 (io.debezium.connector.mysql.BinlogReader:331)
      [2019-04-18 17:58:21,893] INFO Creating thread debezium-mysqlconnector-passkit-io-dev-binlog-client (io.debezium.util.Threads:267)
      [2019-04-18 17:58:21,895] INFO Creating thread debezium-mysqlconnector-passkit-io-dev-binlog-client (io.debezium.util.Threads:267)
      Apr 18, 2019 5:58:21 PM com.github.shyiko.mysql.binlog.BinaryLogClient connect
      INFO: Connected to dev-mysql.passkit.io:3306 at 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 (sid:1, cid:943505)
      [2019-04-18 17:58:21,986] INFO Connected to MySQL binlog at x.x.x.x:3306, starting at GTIDs 5e58cadb-e65a-11e8-98d7-42010a94003b:1-8407886 and binlog file 'mysql-bin.000024', pos=9227581, skipping 0 events plus 1 rows (io.debezium.connector.mysql.BinlogReader:1004)
      [2019-04-18 17:58:21,986] INFO Creating thread debezium-mysqlconnector-passkit-io-dev-binlog-client (io.debezium.util.Threads:267)
      [2019-04-18 17:58:21,986] INFO WorkerSourceTask{id=io-mysql-connector-0} Source task finished initialization and start (org.apache.kafka.connect.runtime.WorkerSourceTask:199)
      [2019-04-18 17:58:22,027] ERROR Error during binlog processing. Last offset stored = null, binlog reader near position = /4 (io.debezium.connector.mysql.BinlogReader:1054)
      [2019-04-18 17:58:22,028] INFO Stopped reading binlog after 0 events, no new offset was recorded (io.debezium.connector.mysql.BinlogReader:992)
      [2019-04-18 17:58:22,386] INFO WorkerSourceTask{id=io-mysql-connector-0} Committing offsets (org.apache.kafka.connect.runtime.WorkerSourceTask:397)
      [2019-04-18 17:58:22,386] INFO WorkerSourceTask{id=io-mysql-connector-0} flushing 0 outstanding messages for offset commit (org.apache.kafka.connect.runtime.WorkerSourceTask:414)
      [2019-04-18 17:58:22,386] ERROR WorkerSourceTask{id=io-mysql-connector-0} Task threw an uncaught and unrecoverable exception (org.apache.kafka.connect.runtime.WorkerTask:177)
      org.apache.kafka.connect.errors.ConnectException: The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires. Error code: 1236; SQLSTATE: HY000.
      	at io.debezium.connector.mysql.AbstractReader.wrap(AbstractReader.java:230)
      	at io.debezium.connector.mysql.AbstractReader.failed(AbstractReader.java:197)
      	at io.debezium.connector.mysql.BinlogReader$ReaderThreadLifecycleListener.onCommunicationFailure(BinlogReader.java:1018)
      	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:950)
      	at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:580)
      	at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:825)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: com.github.shyiko.mysql.binlog.network.ServerException: The slave is connecting using CHANGE MASTER TO MASTER_AUTO_POSITION = 1, but the master has purged binary logs containing GTIDs that the slave requires.
      	at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:914)
      	... 3 more
      [2019-04-18 17:58:22,387] ERROR WorkerSourceTask{id=io-mysql-connector-0} Task is being killed and will not recover until manually restarted (org.apache.kafka.connect.runtime.WorkerTask:178)
      [2019-04-18 17:58:22,387] INFO Stopping MySQL connector task (io.debezium.connector.mysql.MySqlConnectorTask:430)
      [2019-04-18 17:58:22,388] INFO ChainedReader: Stopping the binlog reader (io.debezium.connector.mysql.ChainedReader:121)
      [2019-04-18 17:58:22,388] INFO Discarding 0 unsent record(s) due to the connector shutting down (io.debezium.connector.mysql.BinlogReader:129)
      [2019-04-18 17:58:22,388] INFO Discarding 0 unsent record(s) due to the connector shutting down (io.debezium.connector.mysql.BinlogReader:129)
      [2019-04-18 17:58:22,388] INFO [Producer clientId=io-mysql-connector-dbhistory] Closing the Kafka producer with timeoutMillis = 9223372036854775807 ms. (org.apache.kafka.clients.producer.KafkaProducer:1103)
      [2019-04-18 17:58:22,390] INFO Connector task finished all work and is now shutdown (io.debezium.connector.mysql.MySqlConnectorTask:465)
      [2019-04-18 17:58:22,390] INFO [Producer clientId=producer-9] Closing the Kafka producer with timeoutMillis = 30000 ms. (org.apache.kafka.clients.producer.KafkaProducer:1103)
      
      {
        "name": "io-mysql-connector",
        "config": {
          "connector.class": "io.debezium.connector.mysql.MySqlConnector",
          "tasks.max": "1",
          "database.hostname": "x.x.x.x",
          "database.port": "3306",
          "database.user": "debezium",
          "database.password": "pfr",
          "database.server.id": "1",
          "database.server.name": "passkit-io-dev",
          "database.whitelist": "io",
          "database.history.kafka.bootstrap.servers": "x.x.x.x:9092,x.x.x.x:9092,x.x.x.x:9092",
          "database.history.kafka.topic": "dbhistory.io",
          "snapshot.mode":"when_needed",
          "bigint.unsigned.handling.mode":"precise"
        }
      }
      

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                jpechanec Jiri Pechanec
                Reporter:
                passkit Nick Murray
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: