Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Deadlock when connection try to disconnect #133

Open
aadant opened this issue Nov 29, 2023 · 6 comments
Open

Deadlock when connection try to disconnect #133

aadant opened this issue Nov 29, 2023 · 6 comments

Comments

@aadant
Copy link

aadant commented Nov 29, 2023 

"blc-fpif1-txnrepodbl1:3306" #31833 prio=5 os_prio=0 cpu=3676437.42ms elapsed=146955.63s tid=0x00007fe9bc001800 nid=0x7e58 runnable  [0x00007feb830d3000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketOutputStream.socketWrite0(java.base@11.0.16/Native Method)
        at java.net.SocketOutputStream.socketWrite(java.base@11.0.16/SocketOutputStream.java:110)
        at java.net.SocketOutputStream.write(java.base@11.0.16/SocketOutputStream.java:150)
        at sun.security.ssl.SSLSocketOutputRecord.flush(java.base@11.0.16/SSLSocketOutputRecord.java:271)
        at sun.security.ssl.OutputRecord.changeWriteCiphers(java.base@11.0.16/OutputRecord.java:224)
        at sun.security.ssl.KeyUpdate$KeyUpdateProducer.produce(java.base@11.0.16/KeyUpdate.java:321)
        at sun.security.ssl.KeyUpdate$KeyUpdateKickstartProducer.produce(java.base@11.0.16/KeyUpdate.java:171)
        at sun.security.ssl.SSLHandshake.kickstart(java.base@11.0.16/SSLHandshake.java:538)
        at sun.security.ssl.PostHandshakeContext.kickstart(java.base@11.0.16/PostHandshakeContext.java:68)
        at sun.security.ssl.TransportContext.kickstart(java.base@11.0.16/TransportContext.java:233)
        at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.16/SSLSocketImpl.java:449)
        at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.16/SSLSocketImpl.java:427)
        at sun.security.ssl.SSLSocketImpl.tryKeyUpdate(java.base@11.0.16/SSLSocketImpl.java:1549)
        at sun.security.ssl.SSLSocketImpl.decode(java.base@11.0.16/SSLSocketImpl.java:1521)
        at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base@11.0.16/SSLSocketImpl.java:1476)
        at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@11.0.16/SSLSocketImpl.java:1065)
        at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@11.0.16/SSLSocketImpl.java:972)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readWithinBlockBoundaries(ByteArrayInputStream.java:226)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:207)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readInteger(ByteArrayInputStream.java:52)
        at io.debezium.connector.mysql.RowDeserializers.deserializeDate(RowDeserializers.java:298)
        at io.debezium.connector.mysql.RowDeserializers$WriteRowsDeserializer.deserializeDate(RowDeserializers.java:215)
        at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeCell(AbstractRowsEventDataDeserializer.java:171)
        at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:143)
        at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserializeRows(WriteRowsEventDataDeserializer.java:64)
        at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserialize(WriteRowsEventDataDeserializer.java:56)
        at com.github.shyiko.mysql.binlog.event.deserialization.WriteRowsEventDataDeserializer.deserialize(WriteRowsEventDataDeserializer.java:32)
        at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:337)
        at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246)
        at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:238)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1068)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:648)
        at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:949)
        at java.lang.Thread.run(java.base@11.0.16/Thread.java:829)

"blc-keepalive-fpif1-txnrepodbl1:3306" #31835 prio=5 os_prio=0 cpu=53.87ms elapsed=146955.62s tid=0x00007fe9b8001000 nid=0x7e5a waiting on condition  [0x00007feb8190c000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@11.0.16/Native Method)
        - parking to wait for  <0x00007ff27751cfa0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(java.base@11.0.16/LockSupport.java:194)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.16/AbstractQueuedSynchronizer.java:885)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(java.base@11.0.16/AbstractQueuedSynchronizer.java:917)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@11.0.16/AbstractQueuedSynchronizer.java:1240)
        at java.util.concurrent.locks.ReentrantLock.lock(java.base@11.0.16/ReentrantLock.java:267)
        at sun.security.ssl.SSLSocketImpl.closeNotify(java.base@11.0.16/SSLSocketImpl.java:732)
        at sun.security.ssl.TransportContext.closeNotify(java.base@11.0.16/TransportContext.java:262)
        at sun.security.ssl.TransportContext.initiateOutboundClose(java.base@11.0.16/TransportContext.java:573)
        at sun.security.ssl.TransportContext.closeOutbound(java.base@11.0.16/TransportContext.java:557)
        at sun.security.ssl.SSLSocketImpl.shutdownOutput(java.base@11.0.16/SSLSocketImpl.java:871)
        at com.github.shyiko.mysql.binlog.network.protocol.PacketChannel.close(PacketChannel.java:125)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.disconnectChannel(BinaryLogClient.java:1361)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.terminateConnect(BinaryLogClient.java:1345)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.access$800(BinaryLogClient.java:96)
        at com.github.shyiko.mysql.binlog.BinaryLogClient$5.run(BinaryLogClient.java:894)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.16/Executors.java:515)
        at java.util.concurrent.FutureTask.run(java.base@11.0.16/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.16/ThreadPoolExecutor.java:1128)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.16/ThreadPoolExecutor.java:628)
        at java.lang.Thread.run(java.base@11.0.16/Thread.java:829)

message in the log file

INFO: Keepalive: Trying to restore lost connection to fpif1-txnrepodbl1:3306

waiting forever

Given the code, it looks like this affects master ([0.28.3])
@aadant aadant mentioned this issue Nov 29, 2023
Open
@Naros
Copy link
Collaborator

Naros commented Nov 30, 2023

Hi, so I'm wondering, based on looking at the JDK11 bug history, if this may not be related to some past issues with JDK11 and SSL connections hitting a deadlock scenario where you have this unique combination of the socket shutting down:

https://bugs.openjdk.org/browse/JDK-8207004
https://bugs.openjdk.org/browse/JDK-8207009

Can you please share what JDK vendor you're using? Would it be possible to upgrade to 11.0.20 and see whether this problem goes away, or better yet move to JDK17 as JDK11 is being EoL in October 2024?

@aadant
Copy link
Author

aadant commented Nov 30, 2023

@Naros thanks, looks like it, indeed we use this

# java --version
openjdk 11.0.16 2022-07-19
OpenJDK Runtime Environment 18.9 (build 11.0.16+8)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.16+8, mixed mode, sharing)

@aadant
Copy link
Author

aadant commented Dec 6, 2023

@Naros unfortunately the issue continues to happen with OpenJDK 17 ...

bash-4.4# java --version
openjdk 17.0.2 2022-01-18
OpenJDK Runtime Environment (build 17.0.2+8-86)
OpenJDK 64-Bit Server VM (build 17.0.2+8-86, mixed mode, sharing)

@aadant
Copy link
Author

aadant commented Dec 6, 2023

stack trace involving shyiko :

"blc-fpif1-txnrepodbl1:3306" #77 prio=5 os_prio=0 cpu=3406817.79ms elapsed=71952.46s tid=0x00007feb4423f7a0 nid=0x11a runnable  [0x00007feb5affd000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.FileDispatcherImpl.write0(java.base@17.0.2/Native Method)
        at sun.nio.ch.SocketDispatcher.write(java.base@17.0.2/SocketDispatcher.java:62)
        at sun.nio.ch.NioSocketImpl.tryWrite(java.base@17.0.2/NioSocketImpl.java:398)
        at sun.nio.ch.NioSocketImpl.implWrite(java.base@17.0.2/NioSocketImpl.java:413)
        at sun.nio.ch.NioSocketImpl.write(java.base@17.0.2/NioSocketImpl.java:440)
        at sun.nio.ch.NioSocketImpl$2.write(java.base@17.0.2/NioSocketImpl.java:826)
        at java.net.Socket$SocketOutputStream.write(java.base@17.0.2/Socket.java:1035)
        at sun.security.ssl.SSLSocketOutputRecord.flush(java.base@17.0.2/SSLSocketOutputRecord.java:271)
        at sun.security.ssl.OutputRecord.changeWriteCiphers(java.base@17.0.2/OutputRecord.java:224)
        at sun.security.ssl.KeyUpdate$KeyUpdateProducer.produce(java.base@17.0.2/KeyUpdate.java:321)
        at sun.security.ssl.KeyUpdate$KeyUpdateKickstartProducer.produce(java.base@17.0.2/KeyUpdate.java:171)
        at sun.security.ssl.SSLHandshake.kickstart(java.base@17.0.2/SSLHandshake.java:542)
        at sun.security.ssl.PostHandshakeContext.kickstart(java.base@17.0.2/PostHandshakeContext.java:69)
        at sun.security.ssl.TransportContext.kickstart(java.base@17.0.2/TransportContext.java:251)
        at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@17.0.2/SSLSocketImpl.java:443)
        at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@17.0.2/SSLSocketImpl.java:421)
        at sun.security.ssl.SSLSocketImpl.tryKeyUpdate(java.base@17.0.2/SSLSocketImpl.java:1543)
        at sun.security.ssl.SSLSocketImpl.decode(java.base@17.0.2/SSLSocketImpl.java:1515)
        at sun.security.ssl.SSLSocketImpl.readApplicationRecord(java.base@17.0.2/SSLSocketImpl.java:1474)
        at sun.security.ssl.SSLSocketImpl$AppInputStream.read(java.base@17.0.2/SSLSocketImpl.java:1059)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.readWithinBlockBoundaries(ByteArrayInputStream.java:266)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:245)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.fill(ByteArrayInputStream.java:112)
        at com.github.shyiko.mysql.binlog.io.ByteArrayInputStream.read(ByteArrayInputStream.java:105)
        at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeNewDecimal(AbstractRowsEventDataDeserializer.java:258)
        at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeCell(AbstractRowsEventDataDeserializer.java:169)
        at com.github.shyiko.mysql.binlog.event.deserialization.AbstractRowsEventDataDeserializer.deserializeRow(AbstractRowsEventDataDeserializer.java:143)
        at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserializeRows(UpdateRowsEventDataDeserializer.java:72)
        at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:58)
        at com.github.shyiko.mysql.binlog.event.deserialization.UpdateRowsEventDataDeserializer.deserialize(UpdateRowsEventDataDeserializer.java:33)
        at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.deserializeEventData(EventDeserializer.java:337)
        at com.github.shyiko.mysql.binlog.event.deserialization.EventDeserializer.nextEvent(EventDeserializer.java:246)
        at io.debezium.connector.mysql.MySqlStreamingChangeEventSource$1.nextEvent(MySqlStreamingChangeEventSource.java:238)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.listenForEventPackets(BinaryLogClient.java:1068)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.connect(BinaryLogClient.java:648)
        at com.github.shyiko.mysql.binlog.BinaryLogClient$7.run(BinaryLogClient.java:949)
        at java.lang.Thread.run(java.base@17.0.2/Thread.java:833)

"blc-keepalive-fpif1-txnrepodbl1:3306" #79 prio=5 os_prio=0 cpu=30.29ms elapsed=71952.43s tid=0x00007feb484dd850 nid=0x11c waiting on condition  [0x00007feb5aefd000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.2/Native Method)
        - parking to wait for  <0x00007fefd423e348> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(java.base@17.0.2/LockSupport.java:211)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.2/AbstractQueuedSynchronizer.java:715)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.2/AbstractQueuedSynchronizer.java:938)
        at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@17.0.2/ReentrantLock.java:153)
        at java.util.concurrent.locks.ReentrantLock.lock(java.base@17.0.2/ReentrantLock.java:322)
        at sun.security.ssl.SSLSocketImpl.closeNotify(java.base@17.0.2/SSLSocketImpl.java:726)
        at sun.security.ssl.TransportContext.closeNotify(java.base@17.0.2/TransportContext.java:280)
        at sun.security.ssl.TransportContext.initiateOutboundClose(java.base@17.0.2/TransportContext.java:591)
        at sun.security.ssl.TransportContext.closeOutbound(java.base@17.0.2/TransportContext.java:575)
        at sun.security.ssl.SSLSocketImpl.shutdownOutput(java.base@17.0.2/SSLSocketImpl.java:865)
        at com.github.shyiko.mysql.binlog.network.protocol.PacketChannel.close(PacketChannel.java:125)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.disconnectChannel(BinaryLogClient.java:1361)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.terminateConnect(BinaryLogClient.java:1345)
        at com.github.shyiko.mysql.binlog.BinaryLogClient.access$800(BinaryLogClient.java:96)
        at com.github.shyiko.mysql.binlog.BinaryLogClient$5.run(BinaryLogClient.java:894)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.2/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.2/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.2/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.2/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.2/Thread.java:833)

@Naros
Copy link
Collaborator

Naros commented Dec 7, 2023

Hi @aadant, can you describe the steps on how to reproduce it reliably?

@aadant
Copy link
Author

aadant commented Dec 7, 2023

It happens in the context of debezium embedded
(Altinity sink connector). The problem occurs several times a week. There is an open issue there. It is a random issue though.

acristu added a commit to streamkap-com/mysql-binlog-connector-java that referenced this issue Apr 17, 2024
@acristu
DBZ-7570/osheroff#133: add workaround using SO_LINGER with 0 timeout
a9eb22f
Naros added a commit that referenced this issue Apr 22, 2024
@Naros
Merge pull request #142 from streamkap-com/133-deadlock-when-connecti…
3a1527f 
…on-try-to-disconnect

DBZ-7570/#133: add workaround using SO_LINGER with 0 timeout
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Naros @aadant