Deadlock with Grizzly

[david-katz]

I observed the following deadlock while running 1.1.0RC4 on glassfish 3.1.2.2

"Atmosphere-Shared-AsyncOp-49" - Thread t@148
   java.lang.Thread.State: WAITING
    at sun.misc.Unsafe.park(Native Method)
    - waiting to lock <5bc0cfb> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) owned by "Grizzly-kernel-thread(1)" t@23
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:214)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
    at com.sun.grizzly.tcp.Response.resume(Response.java:765)
    at org.apache.catalina.connector.Request.asyncComplete(Request.java:3993)
    at org.apache.catalina.connector.AsyncContextImpl.complete(AsyncContextImpl.java:242)
    at org.atmosphere.container.Servlet30CometSupport.action(Servlet30CometSupport.java:177)
    at org.atmosphere.container.Servlet30CometSupport.action(Servlet30CometSupport.java:78)
    at org.atmosphere.cpr.AtmosphereResourceImpl.resume(AtmosphereResourceImpl.java:326)
    at org.atmosphere.handler.AbstractReflectorAtmosphereHandler.postStateChange(AbstractReflectorAtmosphereHandler.java:189)
    at org.atmosphere.handler.AbstractReflectorAtmosphereHandler.onStateChange(AbstractReflectorAtmosphereHandler.java:163)
    at org.atmosphere.cpr.DefaultBroadcaster.invokeOnStateChange(DefaultBroadcaster.java:1018)
    at org.atmosphere.cpr.DefaultBroadcaster.prepareInvokeOnStateChange(DefaultBroadcaster.java:1038)
    at org.atmosphere.cpr.DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:914)
    at org.atmosphere.cpr.DefaultBroadcaster$3.run(DefaultBroadcaster.java:578)
    - locked <5534ef82> (a org.atmosphere.cpr.AtmosphereResourceImpl)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
    at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
    at java.util.concurrent.FutureTask.run(FutureTask.java:166)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:722)


"Grizzly-kernel-thread(1)" - Thread t@23
   java.lang.Thread.State: BLOCKED
    at org.atmosphere.cpr.AsynchronousProcessor.completeLifecycle(AsynchronousProcessor.java:473)
    - waiting to lock <5534ef82> (a org.atmosphere.cpr.AtmosphereResourceImpl) owned by "Atmosphere-Shared-AsyncOp-49" t@148
    at org.atmosphere.cpr.AsynchronousProcessor.timedout(AsynchronousProcessor.java:434)
    at org.atmosphere.container.Servlet30CometSupport$CometListener.onTimeout(Servlet30CometSupport.java:222)
    at org.apache.catalina.connector.AsyncContextImpl.notifyAsyncListeners(AsyncContextImpl.java:488)
    - locked <2b8b1910> (a java.util.LinkedList)
    at org.apache.catalina.connector.Request.asyncTimeout(Request.java:4005)
    at org.apache.catalina.connector.Request$6.cancelled(Request.java:3913)
    at org.apache.catalina.connector.Request$6.cancelled(Request.java:3894)
    at com.sun.grizzly.tcp.Response$ResponseAttachment.cancel(Response.java:1097)
    at org.apache.catalina.connector.Request$RequestAttachment.timeout(Request.java:4332)
    at com.sun.grizzly.tcp.Response$ResponseAttachment.onTimeOut(Response.java:1043)
    at com.sun.grizzly.util.SelectionKeyAttachment.timedOut(SelectionKeyAttachment.java:131)
    at com.sun.grizzly.http.KeepAliveThreadAttachment.timedOut(KeepAliveThreadAttachment.java:120)
    at com.sun.grizzly.http.SelectorThreadKeyHandler.expire(SelectorThreadKeyHandler.java:130)
    at com.sun.grizzly.TCPSelectorHandler.postSelect(TCPSelectorHandler.java:526)
    at com.sun.grizzly.SelectorHandlerRunner.doSelect(SelectorHandlerRunner.java:211)
    at com.sun.grizzly.SelectorHandlerRunner.run(SelectorHandlerRunner.java:132)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
    at java.lang.Thread.run(Thread.java:722)

   Locked ownable synchronizers:
    - locked <3e403c23> (a java.util.concurrent.ThreadPoolExecutor$Worker)

    - locked <5bc0cfb> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

[jfarcand]

@rlubke Any idea how I can workaround this issue? Thanks!

[paul-refresh]

Seen in Tomcat 7:

Found one Java-level deadlock:

"Atmosphere-Shared-AsyncOp-59":
waiting to lock monitor 0x00007f4e20028810 (object 0x0000000542ffb720, a org.apache.catalina.websocket.WsOutbound),
which is held by "Atmosphere-Scheduler-10"
"Atmosphere-Scheduler-10":
waiting to lock monitor 0x00007f4e20274020 (object 0x00000005448d6aa8, a org.atmosphere.cpr.AtmosphereResourceImpl),
which is held by "Atmosphere-Shared-AsyncOp-59"

Java stack information for the threads listed above:

"Atmosphere-Shared-AsyncOp-59":
at org.apache.catalina.websocket.WsOutbound.writeTextMessage(WsOutbound.java:165)
- waiting to lock <0x0000000542ffb720> (a org.apache.catalina.websocket.WsOutbound)
at org.atmosphere.container.version.TomcatWebSocket.write(TomcatWebSocket.java:49)
at org.atmosphere.websocket.WebSocket.write(WebSocket.java:152)
at org.atmosphere.websocket.WebSocket.write(WebSocket.java:37)
at org.atmosphere.cpr.AtmosphereResponse$4.write(AtmosphereResponse.java:731)
at org.atmosphere.handler.AbstractReflectorAtmosphereHandler.onStateChange(AbstractReflectorAtmosphereHandler.java:143)
at org.atmosphere.handler.ManagedAtmosphereHandler.invoke(ManagedAtmosphereHandler.java:126)
at org.atmosphere.handler.ManagedAtmosphereHandler.onStateChange(ManagedAtmosphereHandler.java:113)
at org.atmosphere.cpr.DefaultBroadcaster.invokeOnStateChange(DefaultBroadcaster.java:1055)
at org.atmosphere.cpr.DefaultBroadcaster.prepareInvokeOnStateChange(DefaultBroadcaster.java:1075)
at org.atmosphere.cpr.DefaultBroadcaster.executeAsyncWrite(DefaultBroadcaster.java:954)
at org.atmosphere.cpr.DefaultBroadcaster$3.run(DefaultBroadcaster.java:613)
- locked <0x00000005448d6aa8> (a org.atmosphere.cpr.AtmosphereResourceImpl)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:722)
"Atmosphere-Scheduler-10":
at org.atmosphere.cpr.AsynchronousProcessor.completeLifecycle(AsynchronousProcessor.java:438)
- waiting to lock <0x00000005448d6aa8> (a org.atmosphere.cpr.AtmosphereResourceImpl)
at org.atmosphere.cpr.AsynchronousProcessor.cancelled(AsynchronousProcessor.java:545)
at org.atmosphere.container.BlockingIOCometSupport.cancelled(BlockingIOCometSupport.java:196)
at org.atmosphere.cpr.AsynchronousProcessor$AsynchronousProcessorHook.closed(AsynchronousProcessor.java:586)
at org.atmosphere.websocket.DefaultWebSocketProcessor.close(DefaultWebSocketProcessor.java:436)
at org.atmosphere.container.TomcatWebSocketHandler.onClose(TomcatWebSocketHandler.java:80)
at org.apache.catalina.websocket.StreamInbound.doOnClose(StreamInbound.java:222)
at org.apache.catalina.websocket.WsOutbound.doWriteBytes(WsOutbound.java:423)
at org.apache.catalina.websocket.WsOutbound.doWriteText(WsOutbound.java:442)
at org.apache.catalina.websocket.WsOutbound.writeTextMessage(WsOutbound.java:174)
- locked <0x0000000542ffb720> (a org.apache.catalina.websocket.WsOutbound)
at org.atmosphere.container.version.TomcatWebSocket.write(TomcatWebSocket.java:49)
at org.atmosphere.websocket.WebSocket.write(WebSocket.java:152)
at org.atmosphere.websocket.WebSocket.write(WebSocket.java:37)
at org.atmosphere.cpr.AtmosphereResponse$4.write(AtmosphereResponse.java:731)

[rlubke]

@paul-refresh You may want to open a separate issue - the deadlock you've reported is not related to Grizzly.

[rlubke]

@jfarcand Looks like it may be related to https://java.net/jira/browse/GLASSFISH-18503. Pretty sure it's fixed in a later version of 3.1.2.x - but will probably require support to get the fix. Patch included with the issue so it can be fixed locally if desired.

[jfarcand]

@rlubke Thanks.