debezium and mysql-connector problem

[mateusz.s...@futuramo.com]

Hi all,

I've got a problem with kafka-connect/debezium.

My config:

- MySQL database - it works fine, credentials are valid, lets say on db1.server - here I have kafka-connect and debezium

- 3 kafka servers kafka1.server, kafka2.server and kafka3.server

Of course I can use kafkacat directly from db1.server and connect to any topic which I want on kafka*.server hence this is not network problem or sth.

Problem is: debezium does not take events from MySQL due to the following errors (?) (I enabled TRACE log level and I've taken some of suspicious errors):

Sep 11 15:56:19 db1 connect-distributed[14315]: [2018-09-11 15:56:19,422] TRACE [AdminClient clientId=adminclient-1] Client is not ready to send to kafka2.server:9093 (id: 2 rack: null). Must delay 9223372036854775807 ms (org.apache.kafka.clients.admin.KafkaAdminClient:129)
...

Sep 11 16:12:35 db1 connect-distributed[14616]: [2018-09-11 16:12:35,414] DEBUG [Consumer clientId=consumer-1, groupId=kafka-connect-server] Added READ_UNCOMMITTED fetch request for partition connect-offsets-server-4 at offset 0 to node kafka1.server:9093 (id: 1 rack: null) (org.apache.kafka.clients.consumer.internals.Fetcher:195) -- a lot of these

...
Sep 11 16:20:08 db1 connect-distributed[14832]: [2018-09-11 16:20:08,908] DEBUG [Consumer clientId=consumer-1, groupId=kafka-connect-server] Added READ_UNCOMMITTED fetch request for partition connect-offsets-server-17 at offset 2427 to node kafka1.server:9093 (id: 1 rack: null) (org.apache.kafka.clients.consumer.internals.Fetcher:195)

-- And also the below (I suppose these are correct heartbeat)

Sep 11 16:17:07 db1 connect-distributed[14832]: [2018-09-11 16:17:07,049] TRACE Server heartbeat: Event{header=EventHeaderV4{timestamp=0, eventType=HEARTBEAT, serverId=1, headerLength=19, dataLength=20, nextPosition=107593492, flags=0}, data=null} (io.debezium.connector.mysql.BinlogReader:484)

Sep 11 16:17:07 db1 connect-distributed[14832]: [2018-09-11 16:17:07,049] TRACE Received event: Event{header=EventHeaderV4{timestamp=0, eventType=HEARTBEAT, serverId=1, headerLength=19, dataLength=20, nextPosition=107593492, flags=0}, data=null} (io.debezium.connector.mysql.BinlogReader:394)

My config (Taken from TRACE logs)

Sep 11 16:14:45 db1 connect-distributed[14774]: [2018-09-11 16:14:45,046] INFO ConsumerConfig values:
Sep 11 16:14:45 db1 connect-distributed[14774]:         auto.commit.interval.ms = 5000
Sep 11 16:14:45 db1 connect-distributed[14774]:         auto.offset.reset = earliest
Sep 11 16:14:45 db1 connect-distributed[14774]:         bootstrap.servers = [kafka1.server:9093, kafka2.server:9093, kafka3.server:9093]
Sep 11 16:14:45 db1 connect-distributed[14774]:         check.crcs = true
Sep 11 16:14:45 db1 connect-distributed[14774]:         client.id =
Sep 11 16:14:45 db1 connect-distributed[14774]:         connections.max.idle.ms = 540000
Sep 11 16:14:45 db1 connect-distributed[14774]:         enable.auto.commit = false
Sep 11 16:14:45 db1 connect-distributed[14774]:         exclude.internal.topics = true
Sep 11 16:14:45 db1 connect-distributed[14774]:         fetch.max.bytes = 52428800
Sep 11 16:14:45 db1 connect-distributed[14774]:         fetch.max.wait.ms = 500
Sep 11 16:14:45 db1 connect-distributed[14774]:         fetch.min.bytes = 1
Sep 11 16:14:45 db1 connect-distributed[14774]:         group.id = kafka-connect-server
Sep 11 16:14:45 db1 connect-distributed[14774]:         heartbeat.interval.ms = 3000
Sep 11 16:14:45 db1 connect-distributed[14774]:         interceptor.classes = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         internal.leave.group.on.close = true
Sep 11 16:14:45 db1 connect-distributed[14774]:         isolation.level = read_uncommitted
Sep 11 16:14:45 db1 connect-distributed[14774]:         key.deserializer = class org.apache.kafka.common.serialization.ByteArrayDeserializer
Sep 11 16:14:45 db1 connect-distributed[14774]:         max.partition.fetch.bytes = 1048576
Sep 11 16:14:45 db1 connect-distributed[14774]:         max.poll.interval.ms = 300000
Sep 11 16:14:45 db1 connect-distributed[14774]:         max.poll.records = 500
Sep 11 16:14:45 db1 connect-distributed[14774]:         metadata.max.age.ms = 300000
Sep 11 16:14:45 db1 connect-distributed[14774]:         metric.reporters = []
Sep 11 16:14:45 db1 connect-distributed[14774]:         metrics.num.samples = 2
Sep 11 16:14:45 db1 connect-distributed[14774]:         metrics.recording.level = INFO
Sep 11 16:14:45 db1 connect-distributed[14774]:         metrics.sample.window.ms = 30000
Sep 11 16:14:45 db1 connect-distributed[14774]:         partition.assignment.strategy = [class org.apache.kafka.clients.consumer.RangeAssignor]
Sep 11 16:14:45 db1 connect-distributed[14774]:         receive.buffer.bytes = 65536
Sep 11 16:14:45 db1 connect-distributed[14774]:         reconnect.backoff.max.ms = 1000
Sep 11 16:14:45 db1 connect-distributed[14774]:         reconnect.backoff.ms = 50
Sep 11 16:14:45 db1 connect-distributed[14774]:         request.timeout.ms = 305000
Sep 11 16:14:45 db1 connect-distributed[14774]:         retry.backoff.ms = 100
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.jaas.config = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.kerberos.kinit.cmd = /usr/bin/kinit
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.kerberos.min.time.before.relogin = 60000
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.kerberos.service.name = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.kerberos.ticket.renew.jitter = 0.05
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.kerberos.ticket.renew.window.factor = 0.8
Sep 11 16:14:45 db1 connect-distributed[14774]:         sasl.mechanism = GSSAPI
Sep 11 16:14:45 db1 connect-distributed[14774]:         security.protocol = SSL
Sep 11 16:14:45 db1 connect-distributed[14774]:         send.buffer.bytes = 131072
Sep 11 16:14:45 db1 connect-distributed[14774]:         session.timeout.ms = 10000
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.cipher.suites = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.enabled.protocols = [TLSv1.2, TLSv1.1, TLSv1]
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.endpoint.identification.algorithm = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.key.password = [hidden]
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.keymanager.algorithm = SunX509
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.keystore.location = /etc/pki/kafka-client/keystore.jks
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.keystore.password = [hidden]
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.keystore.type = JKS
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.protocol = TLS
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.provider = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.secure.random.implementation = null
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.trustmanager.algorithm = PKIX
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.truststore.location = /etc/pki/kafka-client/truststore.jks
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.truststore.password = [hidden]
Sep 11 16:14:45 db1 connect-distributed[14774]:         ssl.truststore.type = JKS
Sep 11 16:14:45 db1 connect-distributed[14774]:         value.deserializer = class org.apache.kafka.common.serialization.ByteArrayDeserializer
Sep 11 16:14:45 db1 connect-distributed[14774]:  (org.apache.kafka.clients.consumer.ConsumerConfig:238)

So basically Kafka works fine, MySQL works fine but debezium does not grab events.

I will be really appreaciate for any clues.

Thanks in advance,

[Jiri Pechanec]

Hi,

how does your registration request looks like? Do you use filters? Could you please find another messages for logger `io.debezium.connector.mysql.BinlogReader`?

J.