[2.1.2] Deadlock

[Taylor Robison]

We're using http and https and have the traffic passing through nginx.  Play 2.1.1 works fine.  Play 2.1.2 results in timeouts and what appears to be a deadlock.

Any advice?  Other information I can provide?

Here is what jvisualvm shows in my thread dump:

Found one Java-level deadlock:

=============================

"play-internal-execution-context-8":

  waiting to lock monitor 0x00007fbf122d1240 (object 0x00000007f74173c0, a java.lang.Object),

  which is held by "New I/O worker #19"

"New I/O worker #19":

  waiting to lock monitor 0x00007fbf122d0ef8 (object 0x00000007f7417128, a java.lang.Object),

  which is held by "play-internal-execution-context-8"

Java stack information for the threads listed above:

===================================================

"play-internal-execution-context-8":

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.cleanUpWriteBuffer(AbstractNioWorker.java:374)

- waiting to lock <0x00000007f74173c0> (a java.lang.Object)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:349)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:81)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:779)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1458)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:197)

at play.core.server.netty.PlayDefaultUpstreamHandler.exceptionCaught(PlayDefaultUpstreamHandler.scala:37)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.SimpleChannelHandler.exceptionCaught(SimpleChannelHandler.java:156)

at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:130)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.exceptionCaught(SimpleChannelUpstreamHandler.java:153)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:377)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:536)

at org.jboss.netty.handler.ssl.SslHandler.handshake(SslHandler.java:468)

- locked <0x00000007f7417128> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.handleRenegotiation(SslHandler.java:1338)

- locked <0x00000007f7417128> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1238)

- locked <0x00000007f7417128> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1434)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:219)

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:215)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend$1$$anonfun$apply$1.apply(Promise.scala:104)

at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)

at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)

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)

"New I/O worker #19":

at org.jboss.netty.handler.ssl.SslHandler.wrapNonAppData(SslHandler.java:1127)

- waiting to lock <0x00000007f7417128> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1445)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:197)

at org.jboss.netty.channel.ChannelFutureListener$1.operationComplete(ChannelFutureListener.java:41)

at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:427)

at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:413)

at org.jboss.netty.channel.DefaultChannelFuture.setSuccess(DefaultChannelFuture.java:362)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(AbstractNioWorker.java:217)

- locked <0x00000007f74173c0> (a java.lang.Object)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskLoop(AbstractNioWorker.java:150)

at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run(AbstractNioChannel.java:335)

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQueue(AbstractNioSelector.java:366)

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:290)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:88)

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)

at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)

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)

Found one Java-level deadlock:

=============================

"play-internal-execution-context-4":

  waiting to lock monitor 0x00007fbf11cf36e0 (object 0x00000007c2b9bcd8, a java.lang.Object),

  which is held by "New I/O worker #31"

"New I/O worker #31":

  waiting to lock monitor 0x00007fbf11cbb138 (object 0x00000007c2b91be0, a java.lang.Object),

  which is held by "play-internal-execution-context-4"

Java stack information for the threads listed above:

===================================================

"play-internal-execution-context-4":

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.cleanUpWriteBuffer(AbstractNioWorker.java:374)

- waiting to lock <0x00000007c2b9bcd8> (a java.lang.Object)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:349)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.handleAcceptedSocket(NioServerSocketPipelineSink.java:81)

at org.jboss.netty.channel.socket.nio.NioServerSocketPipelineSink.eventSunk(NioServerSocketPipelineSink.java:36)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:779)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1458)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:197)

at play.core.server.netty.PlayDefaultUpstreamHandler.exceptionCaught(PlayDefaultUpstreamHandler.scala:37)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.SimpleChannelHandler.exceptionCaught(SimpleChannelHandler.java:156)

at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:130)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.exceptionCaught(SimpleChannelUpstreamHandler.java:153)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.java:377)

at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:112)

at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791)

at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:536)

at org.jboss.netty.handler.ssl.SslHandler.handshake(SslHandler.java:468)

- locked <0x00000007c2b91be0> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.handleRenegotiation(SslHandler.java:1338)

- locked <0x00000007c2b91be0> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1238)

- locked <0x00000007c2b91be0> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1434)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:219)

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:215)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113)

at play.api.libs.concurrent.PlayPromise$$anonfun$extend$1$$anonfun$apply$1.apply(Promise.scala:104)

at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)

at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)

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)

"New I/O worker #31":

at org.jboss.netty.handler.ssl.SslHandler.wrapNonAppData(SslHandler.java:1127)

- waiting to lock <0x00000007c2b91be0> (a java.lang.Object)

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1445)

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:784)

at org.jboss.netty.channel.SimpleChannelHandler.closeRequested(SimpleChannelHandler.java:334)

at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:260)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)

at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)

at org.jboss.netty.channel.Channels.close(Channels.java:812)

at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:197)

at org.jboss.netty.channel.ChannelFutureListener$1.operationComplete(ChannelFutureListener.java:41)

at org.jboss.netty.channel.DefaultChannelFuture.notifyListener(DefaultChannelFuture.java:427)

at org.jboss.netty.channel.DefaultChannelFuture.notifyListeners(DefaultChannelFuture.java:413)

at org.jboss.netty.channel.DefaultChannelFuture.setSuccess(DefaultChannelFuture.java:362)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(AbstractNioWorker.java:217)

- locked <0x00000007c2b9bcd8> (a java.lang.Object)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskLoop(AbstractNioWorker.java:150)

at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run(AbstractNioChannel.java:335)

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQueue(AbstractNioSelector.java:366)

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:290)

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:88)

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178)

at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)

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)

Found 2 deadlocks.

[James Roper]

Could you set the application logger to trace?  Eg, in application.conf:

logger.application=TRACE

Two things are closing the channel at the same time, I think this should be fine in Netty, but maybe it isn't.  One of the things that is closing the channel is the exception handler in Play, knowing what exception is being thrown may shed more light on the situation.

--
You received this message because you are subscribed to the Google Groups "play-framework" group.
To unsubscribe from this group and stop receiving emails from it, send an email to play-framewor...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

--

James Roper
Software Engineer

Typesafe – Empowering professional developers to build amazing apps.
Twitter: @jroper

[Taylor Robison]

Thanks for the help.  Here is the log data.  

12:06:24.229 [play-internal-execution-context-1] TRACE play - Sending simple result: SimpleResult(304, Map(Date -> Tue, 09 Jul 2013 16:06:24 GMT))

12:06:24.199 [iteratee-execution-context-8] TRACE play - Invoking action with request: GET /common/assets/stylesheets/jslider.plastic.css

12:06:24.198 [play-akka.actor.default-dispatcher-4] TRACE play - Parsing AnyContent as empty

12:06:24.239 [iteratee-execution-context-6] TRACE play - Invoking action with request: GET /common/assets/stylesheets/lib/font-awesome-3.2.1/css/font-awesome.min.css

12:06:24.244 [play-internal-execution-context-8] TRACE play - Sending simple result: SimpleResult(304, Map(Date -> Tue, 09 Jul 2013 16:06:24 GMT))

12:06:24.244 [play-internal-execution-context-8] TRACE play - Sending simple result: SimpleResult(304, Map(Date -> Tue, 09 Jul 2013 16:06:24 GMT))

12:06:24.244 [play-internal-execution-context-8] TRACE play - Sending simple result: SimpleResult(304, Map(Date -> Tue, 09 Jul 2013 16:06:24 GMT))

12:06:24.245 [play-internal-execution-context-8] TRACE play - Sending simple result: SimpleResult(304, Map(Date -> Tue, 09 Jul 2013 16:06:24 GMT))

12:06:24.255 [New I/O worker #25] TRACE play - Http request received by netty: DefaultHttpRequest(chunked: false)

GET /common/requireJsConfig.js HTTP/1.0

Host: localhost

X-Real-IP: 127.0.0.1

X-Forwarded-For: 127.0.0.1

X-Forwarded-Server: localhost

Connection: close

Cache-Control: max-age=0

Accept: */*

User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1559.0 Safari/537.36

DNT: 1

Referer: https://localhost/

Accept-Encoding: gzip,deflate,sdch

Accept-Language: en-US,en;q=0.8

Cookie: region3_registry_menu=visible; menuPanel=visible; menuPanelType=main; PLAY_SESSION=9d74ee51059e8674e383ead5d2dd4179b2aa53ca-mdc-id%3A%5B535b27be-8b81-4e95-8829-9df817aa8b92%5D

12:06:24.268 [New I/O worker #25] TRACE play - Serving this request with: <function1>

12:06:24.268 [play-akka.actor.default-dispatcher-4] TRACE play - Parsing AnyContent as empty

12:06:24.268 [iteratee-execution-context-4] TRACE play - Invoking action with request: GET /common/requireJsConfig.js

12:06:24.280 [play-internal-execution-context-4] TRACE play - Sending simple result: SimpleResult(200, Map(Content-Type -> text/javascript; charset=utf-8))

12:06:24.293 [play-internal-execution-context-1] TRACE application - Exception caught in Netty

javax.net.ssl.SSLException: SSLEngine is closing/closed

at sun.security.ssl.SSLEngineImpl.kickstartHandshake(SSLEngineImpl.java:692) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.beginHandshake(SSLEngineImpl.java:734) ~[na:1.7.0_17]

at org.jboss.netty.handler.ssl.SslHandler.handshake(SslHandler.java:422) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.handleRenegotiation(SslHandler.java:1338) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1238) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1434) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.Channels.close(Channels.java:812) [netty-3.6.5.Final.jar:na]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:219) [play_2.10-2.1.2.jar:2.1.2]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:215) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend$1$$anonfun$apply$1.apply(Promise.scala:104) [play_2.10-2.1.2.jar:2.1.2]

at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24) [scala-library.jar:na]

at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24) [scala-library.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_17]

at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]

Later, I see one of these as well:

12:06:24.340 [New I/O worker #28] TRACE application - Exception caught in Netty

javax.net.ssl.SSLHandshakeException: Invalid Padding length: 180

at sun.security.ssl.Alerts.getSSLException(Alerts.java:192) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1683) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:959) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:884) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:758) ~[na:1.7.0_17]

at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624) ~[na:1.7.0_17]

at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1226) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.decode(SslHandler.java:914) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:425) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:303) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:107) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:312) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:88) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.6.5.Final.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_17]

at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]

Caused by: javax.crypto.BadPaddingException: Invalid Padding length: 180

at sun.security.ssl.CipherBox.removePadding(CipherBox.java:684) ~[na:1.7.0_17]

at sun.security.ssl.CipherBox.decrypt(CipherBox.java:423) ~[na:1.7.0_17]

at sun.security.ssl.InputRecord.decrypt(InputRecord.java:154) ~[na:1.7.0_17]

at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:192) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:953) ~[na:1.7.0_17]

... 17 common frames omitted

Several of these:

12:06:24.481 [play-internal-execution-context-5] TRACE application - Exception caught in Netty

javax.net.ssl.SSLException: SSLEngine is closing/closed

at sun.security.ssl.SSLEngineImpl.kickstartHandshake(SSLEngineImpl.java:692) ~[na:1.7.0_17]

at sun.security.ssl.SSLEngineImpl.beginHandshake(SSLEngineImpl.java:734) ~[na:1.7.0_17]

at org.jboss.netty.handler.ssl.SslHandler.handshake(SslHandler.java:422) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.handleRenegotiation(SslHandler.java:1338) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1238) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1434) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.ssl.SslHandler.handleDownstream(SslHandler.java:591) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:54) ~[netty-3.6.5.Final.jar:na]

at org.jboss.netty.channel.Channels.close(Channels.java:812) [netty-3.6.5.Final.jar:na]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:219) [play_2.10-2.1.2.jar:2.1.2]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$play$core$server$netty$PlayDefaultUpstreamHandler$$handle$1$6$$anonfun$apply$9.apply(PlayDefaultUpstreamHandler.scala:215) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend1$1.apply(Promise.scala:113) [play_2.10-2.1.2.jar:2.1.2]

at play.api.libs.concurrent.PlayPromise$$anonfun$extend$1$$anonfun$apply$1.apply(Promise.scala:104) [play_2.10-2.1.2.jar:2.1.2]

at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24) [scala-library.jar:na]

at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24) [scala-library.jar:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_17]

at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]

Am I doing something horrible?

Taylor

[Taylor Robison]

To avoid this:  http://xkcd.com/979/

Typesafe and the Play solved this problem and the fix is in Play 2.1.5.

https://github.com/playframework/playframework/pull/1623

There is a potential deadlock in netty when using SSL and calling close more than once.  Open issue here: 

https://github.com/netty/netty/issues/1817

I think we saw the issue because Nginx was closing the SSL connection to Play after each request.  I'm speculating that such frequent double closes was triggering the deadlock.

Taylor

On Monday, July 8, 2013 5:52:49 PM UTC-4, Taylor Robison wrote: