Timeout issue when using AsyncCacheApi and custom http filter

[mickaelmagniez]

Play Version

2.9.2

API

Scala 2.13.13

Operating System

Linux 6.5.0-26-generic #26-Ubuntu SMP PREEMPT_DYNAMIC Tue Mar 5 21:19:28 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

JDK

openjdk version "17.0.10" 2024-01-16
OpenJDK Runtime Environment Temurin-17.0.10+7 (build 17.0.10+7)
OpenJDK 64-Bit Server VM Temurin-17.0.10+7 (build 17.0.10+7, mixed mode, sharing)

Library Dependencies

None

Issue Description

When using AsyncCacheApi and having a custom HttpFilter set, AsyncCacheApi.get("key") Future always times out when key exists.

Implemented filter is just the LoggingFilter as describe in documentation, and loaded with

class MyFilters @Inject()(defaultFilters: EnabledFilters, log: LoggingFilter) extends DefaultHttpFilters(defaultFilters.filters :+ log: _*)

Issue is not happening with play framework 2.8.20.

Issue is not happening with ehcache.

Issue is not happening if I remove my custom filter.

Issue is not happening when running test like

val controller = app.injector.instanceOf[ HomeController]
val home = controller.index().apply(FakeRequest(GET, "/"))
status(home) mustBe OK
contentAsString(home) must include ("ok")

Reproducible Test Case

LoggingFilter.scala

class LoggingFilter @Inject()(implicit val mat: Materializer, ec: ExecutionContext) extends Filter with Logging {
  def apply(nextFilter: RequestHeader => Future[Result])(requestHeader: RequestHeader): Future[Result] = {
    nextFilter(requestHeader).map { result =>
      println(s">>> here we are" )
      result
    }
  }
}
class MyFilters @Inject()(defaultFilters: EnabledFilters, log: LoggingFilter) extends DefaultHttpFilters(defaultFilters.filters :+ log: _*)

HomeController.scala

class HomeController @Inject()(
                                val controllerComponents: ControllerComponents,
                                asyncCache: AsyncCacheApi
                              ) extends BaseController {
  def index() = Action { implicit request: Request[AnyContent] =>
    println("-----")
    println(Await.result(asyncCache.get("foo"), 2.seconds))
    println("get1 ok")
    println(Await.result(asyncCache.set("foo", "bar"), 2.seconds))
    println("set ok")
    println(Await.result(asyncCache.get("foo"), 2.seconds))
    println("get2 ok")
    Ok("ok")
  }
}

application.conf

play.http.filters= MyFilters

output

-----
None
get1 ok
Done
set ok
ERROR p.a.h.DefaultHttpErrorHandler - 

! @852b7n1hp - Internal server error, for (GET) [/] ->
 
play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[TimeoutException: Future timed out after [2 seconds]]]
        at play.api.http.HttpErrorHandlerExceptions$.$anonfun$convertToPlayException$2(HttpErrorHandler.scala:400)
        at scala.Option.map(Option.scala:242)
        at play.api.http.HttpErrorHandlerExceptions$.convertToPlayException(HttpErrorHandler.scala:398)
        at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:390)
        at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:267)
        at play.core.server.AkkaHttpServer$$anonfun$invokeAction$1$1.applyOrElse(AkkaHttpServer.scala:482)
        at play.core.server.AkkaHttpServer$$anonfun$invokeAction$1$1.applyOrElse(AkkaHttpServer.scala:474)
        at scala.concurrent.impl.Promise$Transformation.run(Promise.scala:490)
        at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:63)
        at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:100)
Caused by: java.util.concurrent.TimeoutException: Future timed out after [2 seconds]
        at scala.concurrent.impl.Promise$DefaultPromise.tryAwait0(Promise.scala:248)
        at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:261)
        at scala.concurrent.Await$.$anonfun$result$1(package.scala:201)
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:174)
        at java.base/java.util.concurrent.ForkJoinPool.compensatedBlock(ForkJoinPool.java:3451)
        at java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3434)
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:172)
        at akka.dispatch.BatchingExecutor$BlockableBatch.blockOn(BatchingExecutor.scala:116)
        at scala.concurrent.Await$.result(package.scala:124)
        at controllers.HomeController.$anonfun$index$1(HomeController.scala:22)

Complete reproducible test case is available here
Just run

sbt run

and

curl http://localhost:9000

[mickaelmagniez]

Small update : it works if i downgrade with play-caffeine-cache

dependencyOverrides += "com.typesafe.play" %% "play-caffeine-cache" % "2.8.21"

[mkurz]

Might be related to

• Problem with PF v2.9.x/v3.x + async caffeine cache + CompletableFuture.join() #12353

However need some more investigation.