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.

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

The action constructed from an ActionRefiner instance doesn't work in develop mode. #7614

Closed
joymufeng opened this issue Jul 12, 2017 · 13 comments
Closed
Assignees
Labels
Milestone

Comments

@joymufeng
Copy link
Contributor

@joymufeng joymufeng commented Jul 12, 2017

Play Version: 2.6.1

API: Scala

Operating System: Windows 10

JDK: Oracle 1.8.0_111

java version "1.8.0_111"
Java(TM) SE Runtime Environment (build 1.8.0_111-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.111-b14, mixed mode)
Paste the output from java -version at the command line.

Expected Behavior

HomeController.index should works normally in dev mode while constructed from an ActionRefiner instance.

Actual Behavior

Dev Mode

After sereral successful requests to http://localhost:9000/, the later requests will be blocked.

Prod Mode

It works normally.

Code

The index action doesn't work in dev mode:

import javax.inject._
import akka.stream.Materializer
import play.api.mvc._
import scala.concurrent.{ExecutionContext, Future}

@Singleton
class HomeController @Inject()(cc: ControllerComponents)(implicit ec: ExecutionContext, mat: Materializer) extends AbstractController(cc) {
  val userAction = new UserAction(new BodyParsers.Default())

  class UserRequest[A](val user: String, request: Request[A]) extends WrappedRequest[A](request)
  class UserAction @Inject()(val parser: BodyParsers.Default)(implicit val ec: ExecutionContext) extends ActionBuilder[UserRequest, AnyContent] with ActionRefiner[Request, UserRequest] {
    def executionContext = ec
    def refine[A](input: Request[A]) = {
      println("refine ...")
      Future.successful(Left(Results.Ok("Left result.")))
    }
  }

  def index = userAction { implicit request: Request[AnyContent] =>
    Ok("ok")
  }
}

Reproducible Test Case

This demo project will reproduce this issue:
https://github.com/joymufeng/play-scala-starter-example

@joymufeng

This comment has been minimized.

Copy link
Contributor Author

@joymufeng joymufeng commented Jul 12, 2017

It seems to be a bug of ActionBuilder, the folloing codes doesn't work either:

  val userAction1 = new UserAction1(new BodyParsers.Default())
  class UserAction1 @Inject()(val parser: BodyParsers.Default)(implicit val ec: ExecutionContext)
    extends ActionBuilder[Request, AnyContent] {
    def executionContext = ec
    override def invokeBlock[A](request: Request[A], block: (Request[A]) => Future[Result]): Future[Result] = {
      Future.successful("1").flatMap{ s => block(request) } // Doesn't work.
      //block(request) // Works fine.
    }
  }

  def index = userAction1 { implicit request: Request[AnyContent] =>
    Ok("ok")
  }

But block(request) works fine.

@Rovak

This comment has been minimized.

Copy link

@Rovak Rovak commented Jul 12, 2017

I'm running into the same problem. In the following example the index works fine. When calling the buggedIndex action the requests start hanging after a few tries.

class UserRequest[A](val username: Option[String], request: Request[A]) extends WrappedRequest[A](request)

class UserAction @Inject()(val parser: BodyParsers.Default)(implicit val executionContext: ExecutionContext)
  extends ActionBuilder[UserRequest, AnyContent]  {

  override def invokeBlock[A](request: Request[A], block: (UserRequest[A]) => Future[Result]): Future[Result] = {
    block(new UserRequest(request.session.get("username"), request))
  }
}

class UserActionBug @Inject()(val parser: BodyParsers.Default)(implicit val executionContext: ExecutionContext)
  extends ActionBuilder[UserRequest, AnyContent] with ActionTransformer[Request, UserRequest] {
  def transform[A](request: Request[A]) = Future.successful {
    new UserRequest(request.session.get("username"), request)
  }
}

@Singleton
class HomeController @Inject() (userAction: UserAction, userActionBug: UserActionBug, cc: ControllerComponents) extends AbstractController(cc) {

  def index = userAction {
    Ok(views.html.index("Your new application is ready."))
  }

  def buggedIndex = userActionBug {
    Ok(views.html.index("Your new application is ready."))
  }

}

The debugger shows that 2 threads are hanging on https://github.com/playframework/playframework/blob/master/framework/src/play-server/src/main/scala/play/core/server/DevServerStart.scala#L122

@Rovak

This comment has been minimized.

Copy link

@Rovak Rovak commented Jul 12, 2017

#5975 looks related

@richdougherty

This comment has been minimized.

Copy link
Member

@richdougherty richdougherty commented Jul 12, 2017

OK, sounds like some bad stuff happening with threads. I'll take a look. @joymufeng, thanks for the test case, @Rovak thanks for the further debugging and finding that old issue.

@Rovak

This comment has been minimized.

Copy link

@Rovak Rovak commented Jul 12, 2017

@richdougherty the problem doesn't appear in production mode. I made a thread dump which shows the hanging threads https://gist.github.com/Rovak/c10e6d66748e70453abb39448e584c13

@richdougherty

This comment has been minimized.

Copy link
Member

@richdougherty richdougherty commented Jul 12, 2017

OK thanks

@richdougherty

This comment has been minimized.

Copy link
Member

@richdougherty richdougherty commented Jul 13, 2017

I think this is the same issue as #5975, as pointed out by @Rovak.

I think it's got worse in 2.6.1 because we call application.get a lot more now, to avoid using configuration from an outdated application. This change occurred in PR #7556. On the plus side, it's easy to replicate now :)

I'm not sure which is the correct way to fix this. I want to get my head around the different options and tradeoffs.

@Rovak

This comment has been minimized.

Copy link

@Rovak Rovak commented Jul 13, 2017

When i revert the change made in commit 0239503 in the files PlayRequestHandler.scala and DevServerStart.scala then i cannot reproduce the problem.

@wsargent

This comment has been minimized.

Copy link
Member

@wsargent wsargent commented Jul 13, 2017

Seems connected to 0239503#diff-58bf6474fbdd7970aeb1630b24c9f7e2L117 -- somehow there's a single thread that's blocking all the others.

@wsargent the threads are stuck waiting on ApplicationProvider.get @ https://github.com/playframework/playframework/blob/master/framework/src/play-server/src/main/scala/play/core/server/DevServerStart.scala#L113

https://gitter.im/playframework/playframework?at=59667ab5329651f46e7ef53d

I am wondering if 2.12.2 sets an upper limit on the ExecutionContext.global threads or if the project is running into the same thing as akka/akka-http#602 (comment)

@richdougherty

This comment has been minimized.

Copy link
Member

@richdougherty richdougherty commented Jul 13, 2017

Thanks @Rovak and @wsargent.

The debugger shows that 2 threads are hanging on https://github.com/playframework/playframework/blob/master/framework/src/play-server/src/main/scala/play/core/server/DevServerStart.scala#L122

I think the stack trace shows line 122, but it is actually blocking on the surrounding synchronized block. If it was actually blocking on the call to ExecutionContext.global on line 122 then we'd see something like ExecutionContext.Implicits.global$lzyGet in the stack trace.

When i revert the change made in commit 0239503 in the files PlayRequestHandler.scala and DevServerStart.scala then i cannot reproduce the problem.

There are a couple of issues I can see:

  • Each call to Application.get uses 2 threads because of synchronized { Await.result(Future { ... }) }.
  • Application.get is called too often—much more often now because of the change #7556 that was included in 2.6.1. Making us call Application.get less often would require some deep refactoring, so I don't want to change this in 2.6. Maybe something for 2.7.

If I remove the Await.result(Future { ... }) in Application.get and just leave the synchronized { ... } it seems to work OK. However before making a fix I want to understand a bit more why commit 0239503 caused a problem and why using a custom ActionBuilder causes a problem.

In the meantime a workaround might be to increase the number of threads Scala's default ExecutionContext. The system properties can be seen in the source (there are docs somewhere, but source is often clearer!). E.g.

$ export SBT_OPTS="$SBT_OPTS -Dscala.concurrent.context.maxThreads=100"
$ sbt

I had a go and I could still get a deadlock with some fast requests, but it might make it occur less frequently.

@wsargent

This comment has been minimized.

Copy link
Member

@wsargent wsargent commented Jul 14, 2017

Okay, so there are two calls to applicationProvider.get happening at play.core.server.AkkaHttpServer.modelConversion(AkkaHttpServer.scala:184)

  private def modelConversion: AkkaModelConversion =
    reloadCache.cachedFrom(applicationProvider.get).modelConversion

One has the lock and is WAITING:

"application-akka.actor.default-dispatcher-5@17283" prio=5 tid=0x6e nid=NA waiting
  java.lang.Thread.State: WAITING
	 blocks play-dev-mode-akka.actor.default-dispatcher-3@12379
	  at sun.misc.Unsafe.park(Unsafe.java:-1)
	  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
	  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
	  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
	  at scala.concurrent.impl.Promise$DefaultPromise.tryAwait(Promise.scala:238)
	  at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:254)
	  at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:259)
	  at scala.concurrent.Await$.$anonfun$result$1(package.scala:215)
	  at scala.concurrent.Await$$$Lambda$157.1289451892.apply(Unknown Source:-1)
	  at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:167)
	  at akka.dispatch.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java:3641)
	  at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:165)
	  at akka.dispatch.BatchingExecutor$BlockableBatch.blockOn(BatchingExecutor.scala:106)
	  at scala.concurrent.BatchingExecutor$Batch.blockOn(BatchingExecutor.scala:97)
	  at scala.concurrent.Await$.result(package.scala:142)
	  at play.core.server.DevServerStart$$anon$1.get(DevServerStart.scala:200)
	  - locked <0x473f> (a play.core.server.DevServerStart$$anon$1)
	  at play.core.server.AkkaHttpServer.modelConversion(AkkaHttpServer.scala:184)
	  at play.core.server.AkkaHttpServer.$anonfun$executeAction$3(AkkaHttpServer.scala:304)
	  at play.core.server.AkkaHttpServer$$Lambda$1842.1305716121.apply(Unknown Source:-1)

and another one from AkkaHttpServer is blocked on the other one:

"play-dev-mode-akka.actor.default-dispatcher-3@12379" prio=5 tid=0x4c nid=NA waiting for monitor entry
  java.lang.Thread.State: BLOCKED
	 waiting for application-akka.actor.default-dispatcher-5@17283 to release lock on <0x473f> (a play.core.server.DevServerStart$$anon$1)
	  at play.core.server.DevServerStart$$anon$1.get(DevServerStart.scala:122)
	  at play.core.server.AkkaHttpServer.modelConversion(AkkaHttpServer.scala:184)
	  at play.core.server.AkkaHttpServer.handleRequest(AkkaHttpServer.scala:190)
	  at play.core.server.AkkaHttpServer.$anonfun$createServerBinding$3(AkkaHttpServer.scala:107)
	  at play.core.server.AkkaHttpServer$$Lambda$383.1818878724.apply(Unknown Source:-1)
	  at akka.stream.impl.fusing.MapAsync$$anon$23.onPush(Ops.scala:1172)
	  at akka.stream.impl.fusing.GraphInterpreter.processPush(GraphInterpreter.scala:499)
	  at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:462)
	  at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:368)
	  at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:571)
	  at akka.stream.impl.fusing.GraphInterpreterShell$AsyncInput.execute(ActorGraphInterpreter.scala:457)
	  at akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:546)
	  at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:725)
	  at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:740)
	  at akka.actor.Actor.aroundReceive(Actor.scala:513)
	  at akka.actor.Actor.aroundReceive$(Actor.scala:511)
	  at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:650)
	  at akka.actor.ActorCell.receiveMessage(ActorCell.scala:527)
	  at akka.actor.ActorCell.invoke(ActorCell.scala:496)
	  at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
	  at akka.dispatch.Mailbox.run(Mailbox.scala:224)
	  at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
	  at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
	  at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
	  at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
	  at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
@wsargent

This comment has been minimized.

Copy link
Member

@wsargent wsargent commented Jul 14, 2017

Related to #7622

@wsargent

This comment has been minimized.

Copy link
Member

@wsargent wsargent commented Jul 14, 2017

Okay. I think the synchronized block was always a potential problem, and with #7556 there are more opportunities for it to potentially block and exhaust threads, because even in the situation where there is no change of state in the application, there is a lock around the entire section.

I don't think 0239503 is responsible in and of itself, because it's not a question of more threads, but rather "when do you need a read lock vs a write lock" on the application reference.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.