Lagom "requirement failed" in Executor on server stop after all tests

[jibbers42]

I'm posting here since there is no failure in ScalaTest, but the details of the issue are beyond my understanding; let me know if it should be posted elsewhere (like to lagom issues).

repro: https://github.com/jibbers42/lagom-utest-stop-server-issue

When running service tests we have to start a lagom server and then are expected to stop it after that test suite completes. Upon stopping we fail a require inside the Executor.

• start server:

  private val server = ServiceTest.startServer(
    ServiceTest.defaultSetup
      .withCassandra()
  ) { ctx =>
    new HelloApplication(ctx) with LocalServiceLocator
  }
  

  https://github.com/jibbers42/lagom-utest-stop-server-issue/blob/c9ad1021fc09f6678cf43e8c371baa045aa4f7b9/hello-impl/src/test/scala/com/example/hello/impl/HelloServiceTests.scala#L10-L15

• stop server:
  override def utestAfterAll(): Unit = server.stop()
  https://github.com/jibbers42/lagom-utest-stop-server-issue/blob/c9ad1021fc09f6678cf43e8c371baa045aa4f7b9/hello-impl/src/test/scala/com/example/hello/impl/HelloServiceTests.scala#L19

• failed require:
  require(_tasksLocal.get eq null)
  https://github.com/scala/scala/blob/30a1428925497a7358fd386db84fd982c3108707/src/library/scala/concurrent/BatchingExecutor.scala#L51

The test (which returns a Future):

    "say hello" - {
      client.hello("Alice").invoke().map { answer =>
        assert(answer == "Hello, Alice!")
      }

Right now it's just an annoyingly long stack trace, but once I add more suites the failure to stop might become an issue.

ScalaTest session:

sbt> testQuick com.example.hello.impl.HelloServiceSpec
[info] Passed: Total 0, Failed 0, Errors 0, Passed 0
[info] No tests to run for hello/test:testQuick
[info] Passed: Total 0, Failed 0, Errors 0, Passed 0
[info] No tests to run for hello-api/test:testQuick
-------------------------------- Running Tests --------------------------------
03/16 10:31:57 ERROR[main] o.a.c.s.StartupChecks - cassandra.jmx.local.port missing from cassandra-env.sh, unable to start local JMX service.
2018-03-16 10:32:03,437 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task cassandraOffsetStorePrepare.
2018-03-16 10:32:05,282 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task cassandraOffsetStorePrepare done.
2018-03-16 10:32:06,184 ERROR com.lightbend.lagom.internal.broker.kafka.Producer$TaggedOffsetProducerActor - Unable to locate Kafka service named [kafka_native]
[info] HelloServiceSpec:
[info] Hello service
[info] - should say hello
-------------------------------- Running Tests --------------------------------
[info] ScalaTest
[info] Run completed in 16 seconds, 531 milliseconds.
[info] Total number of tests run: 1
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 1, failed 0, canceled 0, ignored 0, pending 0
[info] All tests passed.
[info] utest
[info] Passed: Total 1, Failed 0, Errors 0, Passed 1
[success] Total time: 17 s, completed Mar 16, 2018 10:32:12 AM

uTest session:

sbt> testQuick com.example.hello.impl.HelloServiceTests
[info] Passed: Total 0, Failed 0, Errors 0, Passed 0
[info] No tests to run for hello/test:testQuick
[info] Passed: Total 0, Failed 0, Errors 0, Passed 0
[info] No tests to run for hello-api/test:testQuick
-------------------------------- Running Tests --------------------------------
-------------------------------- Running Tests --------------------------------
03/16 10:31:18 ERROR[main] o.a.c.s.StartupChecks - cassandra.jmx.local.port missing from cassandra-env.sh, unable to start local JMX service.
2018-03-16 10:31:24,074 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task cassandraOffsetStorePrepare.
2018-03-16 10:31:27,214 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task cassandraOffsetStorePrepare done.
2018-03-16 10:31:27,805 ERROR com.lightbend.lagom.internal.broker.kafka.Producer$TaggedOffsetProducerActor - Unable to locate Kafka service named [kafka_native]
+ com.example.hello.impl.HelloServiceTests.say hello 698ms  
2018-03-16 10:31:29,818 WARN  play.api.Play - Error stopping application
java.lang.IllegalArgumentException: requirement failed
	at scala.Predef$.require(Predef.scala:264)
	at scala.concurrent.BatchingExecutor$Batch.run(BatchingExecutor.scala:51)
	at scala.concurrent.Future$InternalCallbackExecutor$.unbatchedExecute(Future.scala:866)
	at scala.concurrent.BatchingExecutor$Batch.blockOn(BatchingExecutor.scala:92)
	at scala.concurrent.Await$.ready(package.scala:142)
	at play.api.Play$.$anonfun$stop$1(Play.scala:145)
	at play.utils.Threads$.withContextClassLoader(Threads.scala:21)
	at play.api.Play$.stop(Play.scala:145)
	at com.lightbend.lagom.scaladsl.testkit.ServiceTest$TestServer.$anonfun$stop$1(ServiceTest.scala:185)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)
	at scala.util.Try$.apply(Try.scala:209)
	at com.lightbend.lagom.scaladsl.testkit.ServiceTest$TestServer.stop(ServiceTest.scala:185)
	at com.example.hello.impl.HelloServiceTests$.utestAfterAll(HelloServiceTests.scala:19)
	at utest.TestRunner$.$anonfun$runAsync$11(TestRunner.scala:102)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)
	at utest.framework.StackMarker$.dropOutside(StackMarker.scala:13)
	at utest.TestRunner$.$anonfun$runAsync$10(TestRunner.scala:102)
	at scala.util.Success.$anonfun$map$1(Try.scala:251)
	at scala.util.Success.map(Try.scala:209)
	at scala.concurrent.Future.$anonfun$map$1(Future.scala:289)
	at scala.concurrent.impl.Promise.liftedTree1$1(Promise.scala:29)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at scala.concurrent.BatchingExecutor$Batch.processBatch$1(BatchingExecutor.scala:63)
	at scala.concurrent.BatchingExecutor$Batch.$anonfun$run$1(BatchingExecutor.scala:78)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)
	at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81)
	at scala.concurrent.BatchingExecutor$Batch.run(BatchingExecutor.scala:55)
	at scala.concurrent.Future$InternalCallbackExecutor$.unbatchedExecute(Future.scala:866)
	at scala.concurrent.BatchingExecutor.execute(BatchingExecutor.scala:106)
	at scala.concurrent.BatchingExecutor.execute$(BatchingExecutor.scala:103)
	at scala.concurrent.Future$InternalCallbackExecutor$.execute(Future.scala:864)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at utest.framework.ExecutionContext$RunNow$.execute(ExecutionContext.scala:16)
	at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:68)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.$anonfun$tryComplete$1$adapted(Promise.scala:284)
	at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:284)
	at scala.concurrent.Promise.complete(Promise.scala:49)
	at scala.concurrent.Promise.complete$(Promise.scala:48)
	at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:183)
	at scala.concurrent.impl.Promise.$anonfun$transform$1(Promise.scala:29)
	at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:60)
	at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
	at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91)
	at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.java:12)
	at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:81)
	at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:91)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)
	at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(ForkJoinExecutorConfigurator.scala:43)
	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)
Tests: 1, Passed: 1, Failed: 0
[info] ScalaTest
[info] Run completed in 14 seconds, 264 milliseconds.
[info] Total number of tests run: 0
[info] Suites: completed 0, aborted 0
[info] Tests: succeeded 0, failed 0, canceled 0, ignored 0, pending 0
[info] No tests were executed.
[info] utest
[info] Passed: Total 1, Failed 0, Errors 0, Passed 1
[success] Total time: 15 s, completed Mar 16, 2018 10:31:30 AM