Deadlock in SubProtocolWebSocketHandler on shutdown with Undertow [SPR-16488]

[spring-projects-issues]

Mathieu Carbou opened SPR-16488 and commented

Probably affects also 4.3.13 because the change log does not seem to fix this issue (https://jira.spring.io/browse/SPR/fixforversion/16354/?selectedTab=com.atlassian.jira.plugins.jira-development-integration-plugin:release-report-tabpanel).

We are using:

• Spring Boot 1.5.8.RELEASE
• Spring Framework 4.3.12.RELEASE

Thread dump extract:

"XNIO-2 I/O-13" #49 prio=5 os_prio=0 tid=0x00007fb110c9a000 nid=0xc482 waiting for monitor entry [0x00007fafd6bef000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.isRunning(SubProtocolWebSocketHandler.java:280)
	- waiting to lock <0x0000000080db6890> (a java.lang.Object)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.checkSessions(SubProtocolWebSocketHandler.java:438)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:311)
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
	at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleMessage(LoggingWebSocketHandlerDecorator.java:56)
	at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleMessage(ExceptionWebSocketHandlerDecorator.java:58)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.delegateMessages(AbstractSockJsSession.java:380)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.handleMessage(WebSocketServerSockJsSession.java:194)
	at org.springframework.web.socket.sockjs.transport.handler.SockJsWebSocketHandler.handleTextMessage(SockJsWebSocketHandler.java:92)
	at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.handleTextMessage(StandardWebSocketHandlerAdapter.java:110)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.access$000(StandardWebSocketHandlerAdapter.java:42)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:81)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:78)
	at io.undertow.websockets.jsr.FrameHandler$7.run(FrameHandler.java:283)
	at io.undertow.websockets.jsr.ServerWebSocketContainer$1.call(ServerWebSocketContainer.java:162)
	at io.undertow.websockets.jsr.ServerWebSocketContainer$1.call(ServerWebSocketContainer.java:159)
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at io.undertow.websockets.jsr.ServerWebSocketContainer.invokeEndpointMethod(ServerWebSocketContainer.java:575)
	at io.undertow.websockets.jsr.ServerWebSocketContainer.invokeEndpointMethod(ServerWebSocketContainer.java:565)
	at io.undertow.websockets.jsr.FrameHandler.invokeTextHandler(FrameHandler.java:263)
	at io.undertow.websockets.jsr.FrameHandler.onFullTextMessage(FrameHandler.java:314)
	at io.undertow.websockets.core.AbstractReceiveListener$2.complete(AbstractReceiveListener.java:156)
	at io.undertow.websockets.core.AbstractReceiveListener$2.complete(AbstractReceiveListener.java:152)
	at io.undertow.websockets.core.BufferedTextMessage.read(BufferedTextMessage.java:105)
	at io.undertow.websockets.core.AbstractReceiveListener.readBufferedText(AbstractReceiveListener.java:152)
	at io.undertow.websockets.core.AbstractReceiveListener.bufferFullMessage(AbstractReceiveListener.java:90)
	at io.undertow.websockets.jsr.FrameHandler.onText(FrameHandler.java:179)
	at io.undertow.websockets.core.AbstractReceiveListener.handleEvent(AbstractReceiveListener.java:44)
	at io.undertow.websockets.core.AbstractReceiveListener.handleEvent(AbstractReceiveListener.java:33)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:932)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:913)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
	at org.xnio.nio.NioSocketConduit.handleReady(NioSocketConduit.java:88)
	at org.xnio.nio.WorkerThread.run(WorkerThread.java:561)

"Thread-11" #71 prio=5 os_prio=0 tid=0x00007fad9c001000 nid=0xccf3 in Object.wait() [0x00007fae29adb000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at io.undertow.server.protocol.framed.AbstractFramedStreamSinkChannel.awaitWritable(AbstractFramedStreamSinkChannel.java:281)
	- locked <0x0000000617eed070> (a java.lang.Object)
	at org.xnio.channels.Channels.writeBlocking(Channels.java:99)
	at io.undertow.websockets.jsr.WebSocketSessionRemoteEndpoint$BasicWebSocketSessionRemoteEndpoint.sendText(WebSocketSessionRemoteEndpoint.java:283)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.sendTextMessage(StandardWebSocketSession.java:203)
	at org.springframework.web.socket.adapter.AbstractWebSocketSession.sendMessage(AbstractWebSocketSession.java:101)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.writeFrameInternal(WebSocketServerSockJsSession.java:222)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.close(AbstractSockJsSession.java:204)
	at org.springframework.web.socket.handler.WebSocketSessionDecorator.close(WebSocketSessionDecorator.java:158)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.close(ConcurrentWebSocketSessionDecorator.java:192)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:258)
	- locked <0x0000000080db6890> (a java.lang.Object)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:272)
	- locked <0x0000000080db6890> (a java.lang.Object)
	at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:231)
	at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:50)
	at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:365)
	at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:204)
	at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:120)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:999)
	at org.springframework.context.support.AbstractApplicationContext$2.run(AbstractApplicationContext.java:929)
	- locked <0x0000000080372f30> (a java.lang.Object)

---

Affects: 4.3.12

Issue Links:

• SubProtocolWebSocketHandler should not log ERROR on "No messages received after ..." [SPR-16409] #20955 SubProtocolWebSocketHandler should not log ERROR on "No messages received after ..."
• Consistent volatile access to running flag in Lifecycle implementations [SPR-16596] #21137 Consistent volatile access to running flag in Lifecycle implementations

Backported to: 4.3.15

[spring-projects-issues]

Mathieu Carbou commented

Note: switching to next Spring Boot version (1.5.9) which depends on Spring FW 4.3.13 might not fix the issue.

[spring-projects-issues]

Juergen Hoeller commented

It turns out that our proactive notifications of all active WebSocket sessions on shutdown shouldn't happen within the lifecycle lock there since they could interfere with a write lock held by the underlying engine (Undertow in this case). We still trigger them within SubProtocolWebSocketHandler.stop() now but outside of the synchronization block.

[spring-projects-issues]

Juergen Hoeller commented

This fix is available in the latest 5.0.4.BUILD-SNAPSHOT as well as 4.3.14.BUILD-SNAPSHOT in the meantime. It'd be great if you could give it an early try!

[spring-projects-issues]

Mathieu Carbou commented

This issue is not fixed.
We have upgraded our app to Spring FW 5.0.4.RELEASE and Spring Boot 2.0.0.RELEASE (which uses Undertow 1.4.22 final).
Our app shutdown is still prevented by a deadlock.

Here is a stack below showing the blocked thread:

"XNIO-2 I/O-14" #58 prio=5 os_prio=0 tid=0x00007f700460c000 nid=0xf6fe waiting for monitor entry [0x00007f70a2eec000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.isRunning(SubProtocolWebSocketHandler.java:286)
	- waiting to lock <0x00000005c1e97308> (a java.lang.Object)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.checkSessions(SubProtocolWebSocketHandler.java:462)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:318)

more details:

2018-03-15 02:39:34
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.162-b12 mixed mode):

"Attach Listener" #7618 daemon prio=9 os_prio=0 tid=0x00007f7058002000 nid=0xd5da waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"SIGTERM handler" #965 daemon prio=9 os_prio=0 tid=0x00007f7058004000 nid=0x32ed waiting for monitor entry [0x00007f7091edd000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at java.lang.Shutdown.exit(Shutdown.java:212)
	- waiting to lock <0x00000000806fc660> (a java.lang.Class for java.lang.Shutdown)
	at java.lang.Terminator$1.handle(Terminator.java:52)
	at sun.misc.Signal$1.run(Signal.java:212)
	at java.lang.Thread.run(Thread.java:748)

"Thread-13" #78 prio=5 os_prio=0 tid=0x00007f6db0001000 nid=0x10090 in Object.wait() [0x00007f70924e2000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000005c2243668> (a java.lang.Object)
	at java.lang.Object.wait(Object.java:502)
	at io.undertow.server.protocol.framed.AbstractFramedStreamSinkChannel.awaitWritable(AbstractFramedStreamSinkChannel.java:281)
	- locked <0x00000005c2243668> (a java.lang.Object)
	at org.xnio.channels.Channels.flushBlocking(Channels.java:64)
	at io.undertow.websockets.jsr.WebSocketSessionRemoteEndpoint$BasicWebSocketSessionRemoteEndpoint.sendText(WebSocketSessionRemoteEndpoint.java:287)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.sendTextMessage(StandardWebSocketSession.java:216)
	at org.springframework.web.socket.adapter.AbstractWebSocketSession.sendMessage(AbstractWebSocketSession.java:100)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.writeFrameInternal(WebSocketServerSockJsSession.java:224)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.close(AbstractSockJsSession.java:210)
	at org.springframework.web.socket.handler.WebSocketSessionDecorator.close(WebSocketSessionDecorator.java:160)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.close(ConcurrentWebSocketSessionDecorator.java:213)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:265)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.stop(SubProtocolWebSocketHandler.java:278)
	- locked <0x00000005c1e97308> (a java.lang.Object)
	at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:236)
	at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:52)
	at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:373)
	at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:209)
	at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:127)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1005)
	at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:933)
	- locked <0x000000008021d4e8> (a java.lang.Object)

"SIGTERM handler" #215 daemon prio=9 os_prio=0 tid=0x00007f7058003800 nid=0x1008f in Object.wait() [0x00007f70925e4000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000005c1e96c68> (a org.springframework.context.support.AbstractApplicationContext$1)
	at java.lang.Thread.join(Thread.java:1252)
	- locked <0x00000005c1e96c68> (a org.springframework.context.support.AbstractApplicationContext$1)
	at java.lang.Thread.join(Thread.java:1326)
	at java.lang.ApplicationShutdownHooks.runHooks(ApplicationShutdownHooks.java:106)
	at java.lang.ApplicationShutdownHooks$1.run(ApplicationShutdownHooks.java:46)
	at java.lang.Shutdown.runHooks(Shutdown.java:123)
	at java.lang.Shutdown.sequence(Shutdown.java:167)
	at java.lang.Shutdown.exit(Shutdown.java:212)
	- locked <0x00000000806fc660> (a java.lang.Class for java.lang.Shutdown)
	at java.lang.Terminator$1.handle(Terminator.java:52)
	at sun.misc.Signal$1.run(Signal.java:212)
	at java.lang.Thread.run(Thread.java:748)

"XNIO-2 I/O-14" #58 prio=5 os_prio=0 tid=0x00007f700460c000 nid=0xf6fe waiting for monitor entry [0x00007f70a2eec000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.isRunning(SubProtocolWebSocketHandler.java:286)
	- waiting to lock <0x00000005c1e97308> (a java.lang.Object)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.checkSessions(SubProtocolWebSocketHandler.java:462)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:318)
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
	at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleMessage(LoggingWebSocketHandlerDecorator.java:56)
	at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleMessage(ExceptionWebSocketHandlerDecorator.java:58)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.delegateMessages(AbstractSockJsSession.java:386)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.handleMessage(WebSocketServerSockJsSession.java:195)
	at org.springframework.web.socket.sockjs.transport.handler.SockJsWebSocketHandler.handleTextMessage(SockJsWebSocketHandler.java:93)
	at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.handleTextMessage(StandardWebSocketHandlerAdapter.java:113)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.access$000(StandardWebSocketHandlerAdapter.java:42)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:84)
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:81)
	at io.undertow.websockets.jsr.FrameHandler$7.run(FrameHandler.java:286)
	at io.undertow.websockets.jsr.ServerWebSocketContainer$1.call(ServerWebSocketContainer.java:162)
	at io.undertow.websockets.jsr.ServerWebSocketContainer$1.call(ServerWebSocketContainer.java:159)
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at io.undertow.websockets.jsr.ServerWebSocketContainer.invokeEndpointMethod(ServerWebSocketContainer.java:575)
	at io.undertow.websockets.jsr.ServerWebSocketContainer.invokeEndpointMethod(ServerWebSocketContainer.java:565)
	at io.undertow.websockets.jsr.FrameHandler.invokeTextHandler(FrameHandler.java:266)
	at io.undertow.websockets.jsr.FrameHandler.onFullTextMessage(FrameHandler.java:317)
	at io.undertow.websockets.core.AbstractReceiveListener$2.complete(AbstractReceiveListener.java:156)
	at io.undertow.websockets.core.AbstractReceiveListener$2.complete(AbstractReceiveListener.java:152)
	at io.undertow.websockets.core.BufferedTextMessage.read(BufferedTextMessage.java:105)
	at io.undertow.websockets.core.AbstractReceiveListener.readBufferedText(AbstractReceiveListener.java:152)
	at io.undertow.websockets.core.AbstractReceiveListener.bufferFullMessage(AbstractReceiveListener.java:90)
	at io.undertow.websockets.jsr.FrameHandler.onText(FrameHandler.java:182)
	at io.undertow.websockets.core.AbstractReceiveListener.handleEvent(AbstractReceiveListener.java:44)
	at io.undertow.websockets.core.AbstractReceiveListener.handleEvent(AbstractReceiveListener.java:33)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:942)
	at io.undertow.server.protocol.framed.AbstractFramedChannel$FrameReadListener.handleEvent(AbstractFramedChannel.java:923)
	at org.xnio.ChannelListeners.invokeChannelListener(ChannelListeners.java:92)
	at org.xnio.conduits.ReadReadyHandler$ChannelListenerHandler.readReady(ReadReadyHandler.java:66)
	at org.xnio.nio.NioSocketConduit.handleReady(NioSocketConduit.java:88)
	at org.xnio.nio.WorkerThread.run(WorkerThread.java:561)

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f71380ac000 nid=0xf187 in Object.wait() [0x00007f70b22e1000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x0000000080209418> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
	- locked <0x0000000080209418> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f71380a7800 nid=0xf186 in Object.wait() [0x00007f70b23e2000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x0000000080209648> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

[spring-projects-issues]

Juergen Hoeller commented

It looks like our enforced lock in SubProtocolWebSocketHandler.isRunning() is a culprit as well. I've revisited all of our Lifecycle implementation to consistently use a volatile field without a full lock for their isRunning() implementation (#21137), which on its own might be sufficient to resolve your issue here (since one of our your threads is stuck exactly there).

I'll let you know once this is available in a snapshot. Please prepare for giving it a try before the 5.0.5 / 4.3.15 release, making sure that the issue is gone for good now.

[spring-projects-issues]

Juergen Hoeller commented

5.0.5.BUILD-SNAPSHOT includes the #21137 refinement for SubProtocolWebSocketHandler.isRunning() now. Please give it a try; if any deadlock potential against Undertow remains, let's figure it out ASAP. See https://projects.spring.io/spring-framework/ for the Maven coordinates for the latest 5.0.5 snapshot.

[spring-projects-issues]

Mathieu Carbou commented

Hi,
I'll see if I can do something to test it.
What is really hard is that the issue occurs about less than 30% of the time on some integration tests we have when ran in our Jenkins environment. I wasn't able to reproduce locally in a reproductible way. Probably the number of CPU and speed has to do with it...
And the way or CI works, using snapshots might not be possible but I have to confirm.

UPDATE:
So even if we manage to run successive builds that are successful, we won't be able to confirm that the issue is resolved.

[spring-projects-issues]

Juergen Hoeller commented

Alright, I'm considering this one as resolved since I don't see any remaining deadlock potential that we could address on our end. Your thread dump indicates that Undertow itself possibly uses several locks within its processing arrangement which implies some deadlock potential on that end as well, but that's outside of our powers.

Please note: #21137 has yet to be backported to the 4.3.x branch; I'll include it in my next round of backports early next week. So for the time being, the above-mentioned refinement is only available in 5.0.5 snapshots.

[spring-projects-issues]

Mathieu Carbou commented

Hi,
Just to let you know that we were able to test with the snapshot since a few days and we didn't this issue anymore.

[spring-projects-issues]

Juergen Hoeller commented

Thanks for the feedback! That's great to hear.