What happens during Play! controller instantiation?

Question

I experience strange behavior within controllers in Play framework. I am using elastic4s to connect to an Elasticsearch cluster, and depending precise timing of establishing the connection it either works or it doesn't. My minimal-so-far example looks like this:

class EsController extends Controller {


  def buildClient() = ElasticClient.transport(Settings.builder
      .put("cluster.name", "es").build,
    "127.0.0.1:9300")

  val eagerClient = buildClient()
  lazy val lazyClient = buildClient()


  object ElasticConnection extends ElasticDsl {

    def eagerStats = eagerClient.execute(get cluster stats)

    def lazyStats = lazyClient.execute(get cluster stats)
  }

  // accessible via GET /eagerStats
  def eagerStats = Action.async {
    ElasticConnection.eagerStats map (s => Ok(s.toString))
  }

  // accessible via GET /lazyStats
  def lazyStats = Action.async {
    ElasticConnection.lazyStats map (s => Ok(s.toString))
  }
}

I start the app via sbt run. Then I can try getting the two endpoints. curl localhost:9000/lazyStats/ works fine, talks to my ES node and returns proper stats. curl localhost:9000/eagerStats/ throws an exception from ES transport layer (stack trace at the end). Since my code is identical in both cases (the only difference being val vs lazy val) I suppose the constructor is instantiated in a weird fashion. Can anyone confirm or deny that?

As a sidenote, I could create a separate class that handles the ES connection and @Inject it (probably making it also a @Singleton) - and that would probably be the preferred solution. I find the described behavior weird, though, and I'd be glad to see an explanation.

The elastic4s is a small wrapper around the official ES Java driver, and I'm quite confident there is no magic happening there in this scenario.

UPDATE: I'm running a single-node ES cluster on the same machine as a standalone process. It's configured properly, it even has a kopf plugin up and running. REST interface works fine; transport interface works too, provided that I use the lazily initalized connection.

I'm using ES 2.2.0 (both client- and server-side), Play 2.4.6, scala 2.11.7 and SBT 0.13.8.

The stack trace from the eager connection:

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[NoNodeAvailableException: None of the configured nodes are available: [{#transport#-1}{127.0.0.1}{127.0.0.1:9300}]]]
at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.6.jar:2.4.6]
at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.6.jar:2.4.6]
at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.6.jar:2.4.6]
at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:151) [play-netty-server_2.11-2.4.6.jar:2.4.6]
at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:148) [play-netty-server_2.11-2.4.6.jar:2.4.6]
at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:36) [scala-library-2.11.7.jar:na]
at scala.util.Failure$$anonfun$recover$1.apply(Try.scala:216) [scala-library-2.11.7.jar:na]
at scala.util.Try$.apply(Try.scala:192) [scala-library-2.11.7.jar:na]
at scala.util.Failure.recover(Try.scala:216) [scala-library-2.11.7.jar:na]
at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.7.jar:na]
at play.api.libs.iteratee.Execution$trampoline$.executeScheduled(Execution.scala:109) [play-iteratees_2.11-2.4.6.jar:2.4.6]
at play.api.libs.iteratee.Execution$trampoline$.execute(Execution.scala:71) [play-iteratees_2.11-2.4.6.jar:2.4.6]
at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:40) [scala-library-2.11.7.jar:na]
at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:248) [scala-library-2.11.7.jar:na]
at scala.concurrent.Promise$class.complete(Promise.scala:55) [scala-library-2.11.7.jar:na]
at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:153) [scala-library-2.11.7.jar:na]
at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:23) [scala-library-2.11.7.jar:na]
at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40) [akka-actor_2.11-2.3.13.jar:na]
at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397) [akka-actor_2.11-2.3.13.jar:na]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.7.jar:na]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.7.jar:na]
Caused by: org.elasticsearch.client.transport.NoNodeAvailableException: None of the configured nodes are available: [{#transport#-1}{127.0.0.1}{127.0.0.1:9300}]
at org.elasticsearch.client.transport.TransportClientNodesService.ensureNodesAreAvailable(TransportClientNodesService.java:290) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.client.transport.TransportClientNodesService.execute(TransportClientNodesService.java:207) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.client.transport.support.TransportProxyClient.execute(TransportProxyClient.java:55) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.client.transport.TransportClient.doExecute(TransportClient.java:286) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.client.support.AbstractClient.execute(AbstractClient.java:351) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.client.support.AbstractClient$ClusterAdmin.execute(AbstractClient.java:845) ~[elasticsearch-2.2.0.jar:2.2.0]
at org.elasticsearch.action.ActionRequestBuilder.execute(ActionRequestBuilder.java:85) ~[elasticsearch-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.admin.ClusterDsl$ClusterStatsExecutable$$anonfun$apply$2.apply(ClusterDsl.scala:24) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.admin.ClusterDsl$ClusterStatsExecutable$$anonfun$apply$2.apply(ClusterDsl.scala:24) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.Executable$class.injectFuture(Executable.scala:30) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.admin.ClusterDsl$ClusterStatsExecutable$.injectFuture(ClusterDsl.scala:21) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.admin.ClusterDsl$ClusterStatsExecutable$.apply(ClusterDsl.scala:24) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.admin.ClusterDsl$ClusterStatsExecutable$.apply(ClusterDsl.scala:21) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at com.sksamuel.elastic4s.ElasticClient.execute(ElasticClient.scala:20) ~[elastic4s-core_2.11-2.2.0.jar:2.2.0]
at controllers.BookController$ElasticConnection$.eagerStats(BookController.scala:35) ~[classes/:na]
at controllers.BookController$$anonfun$eagerStats$1.apply(BookController.scala:41) ~[classes/:na]
at controllers.BookController$$anonfun$eagerStats$1.apply(BookController.scala:41) ~[classes/:na]
at play.api.mvc.ActionBuilder$$anonfun$async$1.apply(Action.scala:456) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.ActionBuilder$$anonfun$async$1.apply(Action.scala:456) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$.invokeBlock(Action.scala:533) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$.invokeBlock(Action.scala:530) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.ActionBuilder$$anon$1.apply(Action.scala:493) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$$anonfun$apply$1$$anonfun$apply$4$$anonfun$apply$5.apply(Action.scala:105) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$$anonfun$apply$1$$anonfun$apply$4$$anonfun$apply$5.apply(Action.scala:105) ~[play_2.11-2.4.6.jar:2.4.6]
at play.utils.Threads$.withContextClassLoader(Threads.scala:21) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$$anonfun$apply$1$$anonfun$apply$4.apply(Action.scala:104) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$$anonfun$apply$1$$anonfun$apply$4.apply(Action.scala:103) ~[play_2.11-2.4.6.jar:2.4.6]
at scala.Option.map(Option.scala:146) ~[scala-library-2.11.7.jar:na]
at play.api.mvc.Action$$anonfun$apply$1.apply(Action.scala:103) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.mvc.Action$$anonfun$apply$1.apply(Action.scala:96) ~[play_2.11-2.4.6.jar:2.4.6]
at play.api.libs.iteratee.DoneIteratee$$anonfun$mapM$2.apply(Iteratee.scala:741) ~[play-iteratees_2.11-2.4.6.jar:2.4.6]
at play.api.libs.iteratee.DoneIteratee$$anonfun$mapM$2.apply(Iteratee.scala:741) ~[play-iteratees_2.11-2.4.6.jar:2.4.6]
at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24) [scala-library-2.11.7.jar:na]
at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24) [scala-library-2.11.7.jar:na]
... 6 common frames omitted

Where is the ES server created. Is that running as another process or are you starting a local node elsewhere in your play app? — sksamuel, Feb 17 '16 at 01:32
As a separate process, sorry for putting it clear. I updated the question. — Wojciech Ptak, Feb 17 '16 at 12:41
Can you try a try catch around the eager and see if its throwing somethin. — sksamuel, Feb 17 '16 at 12:58
`val eagerClient = buildClient()` does not throw; calling `eagerStats` throws the exception mentioned above. Not sure what are you asking about... My theory is that the eager client is initlaized improperly due to some weird constructor/initialization fiasco, and the exception is thrown because the eager client is misconfigured. I have no arguments to back it up, though. — Wojciech Ptak, Feb 17 '16 at 13:41

score 1 · Answer 1 · answered Feb 17 '16 at 20:24

It turned out to be a weird race condition, so you might as well stop reading now.

Here is my hypothesis on what happens:

The race condition is caused by the way ES java driver handles connections, and has nothing to do with Play or elastic4s.

ElasticClient.transport(...) does not block until connection is established; it only initializes the driver with given settings. This causes the driver to try and connect to ES cluster, but the connection attempt is asynchronous under the hood. If the driver manages to establish connection before any API calls are requested, everything works. If, on the other hand, any API call is made right after driver initialization and there is no connection yet, the API call fails with this exact exception. In usual conditions, this all happens very fast and causes no trouble. I suspect that running from interactive sbt session adds complexity because of Play autoreloading - memory is limited (part consumed by SBT itself), and JVM is under heavy load, because the compilation, Play bootstrap and ES connection init are all happening on request.

What happens during Play! controller instantiation?

1 Answers1