Loading...

Type: Bug
Resolution: Unresolved
Priority: Major
Fix Version/s: 1.9-backlog, 2.4-backlog
Affects Version/s: None
Component/s: mysql-connector
Labels:
None

Blocked:
False
Blocked Reason:
None
Ready:
False

SFDC Cases Counter:
SFDC Cases Links:

Hello,

I'm using latest 1.9.Final version of Debezium against openjdk-11 / Debian 10 OS.

On several MySQL databases (8.0.25), I get an ERROR (100 % reproducible on the affected databases) during the initial snapshot.

The traditional ResultSet streaming hangs on certain big tables (rs.next() does not return after a long while).
MySQL kills the connection after the net write_timeout (600s).

Task threw an uncaught and unrecoverable exception. Task is being killed and will not recover until manually restarted (org.apache.kafka.connect.runtime.WorkerTask)
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.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:115)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: io.debezium.DebeziumException: java.lang.RuntimeException: java.sql.SQLException: Streaming result set com.mysql.cj.protocol.a.result.ResultsetRowsStreaming@51ad4aeb is still active. No statements may be issued when any streaming result sets are open and in use on a given connection. Ensure that you have called .close() on any active streaming result sets before attempting more queries.
    at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:85)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.doSnapshot(ChangeEventSourceCoordinator.java:153)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:135)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:108)
    ... 5 more
Caused by: java.lang.RuntimeException: java.sql.SQLException: Streaming result set com.mysql.cj.protocol.a.result.ResultsetRowsStreaming@51ad4aeb is still active. No statements may be issued when any streaming result sets are open and in use on a given connection. Ensure that you have called .close() on any active streaming result sets before attempting more queries.
    at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:520)
    at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:143)
    at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:76)
    ... 8 more
Caused by: java.sql.SQLException: Streaming result set com.mysql.cj.protocol.a.result.ResultsetRowsStreaming@51ad4aeb is still active. No statements may be issued when any streaming result sets are open and in use on a given connection. Ensure that you have called .close() on any active streaming result sets before attempting more queries.
    at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:129)
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:122)
    at com.mysql.cj.jdbc.ConnectionImpl.rollbackNoChecks(ConnectionImpl.java:1932)
    at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1826)
    at io.debezium.relational.RelationalSnapshotChangeEventSource.rollbackTransaction(RelationalSnapshotChangeEventSource.java:517)
    ... 10 more

Debezium hangs here : https://github.com/debezium/debezium/blob/v1.9.0.Alpha2/debezium-core/src/main/java/io/debezium/relational/RelationalSnapshotChangeEventSource.java#L362 (added trace info to find the issue).

As vjuranek@redhat.com suggested, I reproduced the issue (simple task restart to rerun the failed initial snapshot and then wait for the moment no more data are being processed) and got thread stack dumps :

"task-thread-xxxxxx-0" #1265 prio=5 os_prio=0 cpu=11168613.05ms elapsed=11830.39s tid=0x00007fdef8131800 nid=0x8df in Object.wait()  [0x00007fe095067000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(java.base@11.0.14/Native Method)
    - waiting on <no object reference available>
    at io.debezium.connector.base.ChangeEventQueue.poll(ChangeEventQueue.java:249)
    - waiting to re-lock in wait() <0x00007fe2760c8ee0> (a io.debezium.connector.base.ChangeEventQueue)
    at io.debezium.connector.mysql.MySqlConnectorTask.doPoll(MySqlConnectorTask.java:214)
    at io.debezium.connector.common.BaseSourceTask.poll(BaseSourceTask.java:160)
    at org.apache.kafka.connect.runtime.WorkerSourceTask.poll(WorkerSourceTask.java:304)
    at org.apache.kafka.connect.runtime.WorkerSourceTask.execute(WorkerSourceTask.java:248)
    at org.apache.kafka.connect.runtime.WorkerTask.doRun(WorkerTask.java:188)
    at org.apache.kafka.connect.runtime.WorkerTask.run(WorkerTask.java:243)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.14/Executors.java:515)
    at java.util.concurrent.FutureTask.run(java.base@11.0.14/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.14/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.14/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.14/Thread.java:829)"debezium-mysqlconnector-xxxxxx-change-event-source-coordinator" #1271 prio=5 os_prio=0 cpu=7966682.34ms elapsed=11819.87s tid=0x00007fdfbc019000 nid=0x8f9 runnable  [0x00007fdfd8caa000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketOutputStream.socketWrite0(java.base@11.0.14/Native Method)
    at java.net.SocketOutputStream.socketWrite(java.base@11.0.14/SocketOutputStream.java:110)
    at java.net.SocketOutputStream.write(java.base@11.0.14/SocketOutputStream.java:150)
    at sun.security.ssl.SSLSocketOutputRecord.flush(java.base@11.0.14/SSLSocketOutputRecord.java:266)
    at sun.security.ssl.OutputRecord.changeWriteCiphers(java.base@11.0.14/OutputRecord.java:219)
    at sun.security.ssl.KeyUpdate$KeyUpdateProducer.produce(java.base@11.0.14/KeyUpdate.java:321)
    at sun.security.ssl.KeyUpdate$KeyUpdateKickstartProducer.produce(java.base@11.0.14/KeyUpdate.java:171)
    at sun.security.ssl.SSLHandshake.kickstart(java.base@11.0.14/SSLHandshake.java:538)
    at sun.security.ssl.PostHandshakeContext.kickstart(java.base@11.0.14/PostHandshakeContext.java:68)
    at sun.security.ssl.TransportContext.kickstart(java.base@11.0.14/TransportContext.java:232)
    at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.14/SSLSocketImpl.java:444)
    at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.14/SSLSocketImpl.java:422)
    at sun.security.ssl.SSLSocketImpl.tryKeyUpdate(java.base@11.0.14/SSLSocketImpl.java:1544)
    at sun.security.ssl.SSLSocketImpl.decode(java.base@11.0.14/SSLSocketImpl.java:1516)
    at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base@11.0.14/SSLSocketImpl.java:1471)
    at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@11.0.14/SSLSocketImpl.java:1060)
    at java.io.FilterInputStream.read(java.base@11.0.14/FilterInputStream.java:133)
    at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
    at com.mysql.cj.protocol.a.SimplePacketReader.readMessageLocal(SimplePacketReader.java:137)
    at com.mysql.cj.protocol.a.SimplePacketReader.readMessage(SimplePacketReader.java:102)
    at com.mysql.cj.protocol.a.SimplePacketReader.readMessage(SimplePacketReader.java:45)
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readMessage(TimeTrackingPacketReader.java:62)
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readMessage(TimeTrackingPacketReader.java:41)
    at com.mysql.cj.protocol.a.MultiPacketReader.readMessage(MultiPacketReader.java:66)
    at com.mysql.cj.protocol.a.MultiPacketReader.readMessage(MultiPacketReader.java:44)
    at com.mysql.cj.protocol.a.ResultsetRowReader.read(ResultsetRowReader.java:75)
    at com.mysql.cj.protocol.a.ResultsetRowReader.read(ResultsetRowReader.java:42)
    at com.mysql.cj.protocol.a.NativeProtocol.read(NativeProtocol.java:1587)
    at com.mysql.cj.protocol.a.result.ResultsetRowsStreaming.next(ResultsetRowsStreaming.java:194)
    at com.mysql.cj.protocol.a.result.ResultsetRowsStreaming.next(ResultsetRowsStreaming.java:62)
    at com.mysql.cj.jdbc.result.ResultSetImpl.next(ResultSetImpl.java:1779)
    - locked <0x00007fe2760da290> (a com.mysql.cj.jdbc.ConnectionImpl)
    at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEventsForTable(RelationalSnapshotChangeEventSource.java:362)
    at io.debezium.relational.RelationalSnapshotChangeEventSource.createDataEvents(RelationalSnapshotChangeEventSource.java:309)
    at io.debezium.relational.RelationalSnapshotChangeEventSource.doExecute(RelationalSnapshotChangeEventSource.java:129)
    at io.debezium.pipeline.source.AbstractSnapshotChangeEventSource.execute(AbstractSnapshotChangeEventSource.java:76)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.doSnapshot(ChangeEventSourceCoordinator.java:153)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.executeChangeEventSources(ChangeEventSourceCoordinator.java:135)
    at io.debezium.pipeline.ChangeEventSourceCoordinator.lambda$start$0(ChangeEventSourceCoordinator.java:108)
    at io.debezium.pipeline.ChangeEventSourceCoordinator$$Lambda$1358/0x00007fdec38f1900.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.14/Executors.java:515)
    at java.util.concurrent.FutureTask.run(java.base@11.0.14/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.14/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.14/ThreadPoolExecutor.java:628)
    at java.lang.Thread.run(java.base@11.0.14/Thread.java:829)   Locked ownable synchronizers:
    - <0x00007fe27617ce08> (a java.util.concurrent.ThreadPoolExecutor$Worker)
    - <0x00007fe2765485b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x00007fe276548690> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x00007fe276548718> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x00007fe276548760> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

As SSL seemed to be the reason i retried with "database.ssl.mode": "disabled" and it worked flawlessly. But sadly it means security risks as data can be read easily.

There seems to be a leak with JDBC MySQL and SSL.

Details

Description

Attachments

Activity

People

Dates