Entity testing raising exception trying to connect to Cassandra

Lagom
1

I’m using Lagom 1.6.0-M5. I defined an Entity Spec test which uses the PersistentEntityTestDriver which allows to run the test without database as described here: https://www.lagomframework.com/documentation/1.5.x/scala/PersistentEntity.html#Unit-Testing

However when running the test I got errors because during the test it tries to connect to Cassandra:

09/04 18:59:41 ERROR[main] o.a.c.s.StartupChecks - cassandra.jmx.local.port missing from cassandra-env.sh, unable to start local JMX service.
2019-09-04 18:59:46,997 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
java.util.concurrent.ExecutionException: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (tried: /127.0.0.1:63091 (com.datastax.driver.core.exceptions.BusyPoolException: [/127.0.0.1] Pool is busy (no available connection and the queue has reached its max size 0)))

I don’t understand why it is trying to connect to the database during the test because when I run the Hello example there is no such errors.

Any idea ?

2

PersistentEntityTestDriver doesn’t try to connect to a real database, it runs the entity entirely in memory. So, there must be something else in your test that is trying to connect to the database. Are you able to share the code?

3

I did a mistake. It is not the Entity Spec test but the Service Spec test.

Here is the code:

class CountryServiceSpec extends AsyncWordSpec with Matchers with BeforeAndAfterAll {

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

  val client = server.serviceClient.implement[CountryService]

  override protected def afterAll() = server.stop()

  "Country service" should {
    "create country" in {
      client.createCountry.invoke(CountryCreation("dschoen", Some(66L), "switzerland.gif", "CH", "Switzerland", "EMEA")).map { answer =>
        answer should ===(Done)
      }
    }
  }
}

I agree that there is a “withCassandra()” which may cause the problem but I took this code from the Hello Lagom example and in that example there is no errors.

4

I can’t spot anything wrong in the source code. Could you share the complete log output from the test run?

5

Yes here is the log:

> test
[info] CountryEntitySpec:
[info] Customer entity
[WARN] [SECURITY][09/06/2019 12:13:44.373] [pool-1-thread-1-ScalaTest-running-CountryEntitySpec] [akka.serialization.Serialization(akka://CountryEntitySpec)] Using the default Java serializer for class [com.nagravision.country.impl.CountryCreated] which is not recommended because of performance implications. Use another serializer or disable this warning using the setting 'akka.actor.warn-about-java-serializer-usage'
[WARN] [SECURITY][09/06/2019 12:13:44.384] [pool-1-thread-1-ScalaTest-running-CountryEntitySpec] [akka.serialization.Serialization(akka://CountryEntitySpec)] Using the default Java serializer for class [com.nagravision.country.impl.Country] which is not recommended because of performance implications. Use another serializer or disable this warning using the setting 'akka.actor.warn-about-java-serializer-usage'
[info] - should create country command 
12:13:45.087 [warn] akka.stream.scaladsl.RestartWithBackoffSource [sourceThread=user-impl-application-akka.actor.default-dispatcher-30, akkaTimestamp=10:13:45.087UTC, akkaSource=RestartWithBackoffSource(akka://user-impl-application), sourceActorSystem=user-impl-application] - Restarting graph due to failure. stack_trace: 
java.util.concurrent.ExecutionException: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (no host was tried)
	at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:552)
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:513)
	at akka.persistence.cassandra.package$ListenableFutureConverter$$anon$2.$anonfun$run$2(package.scala:25)
	at scala.util.Try$.apply(Try.scala:209)
	at akka.persistence.cassandra.package$ListenableFutureConverter$$anon$2.run(package.scala:25)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (no host was tried)
	at com.datastax.driver.core.RequestHandler.reportNoMoreHosts(RequestHandler.java:265)
	at com.datastax.driver.core.RequestHandler.access$1200(RequestHandler.java:62)
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution.findNextHostAndQuery(RequestHandler.java:357)
	at com.datastax.driver.core.RequestHandler.startNewExecution(RequestHandler.java:138)
	at com.datastax.driver.core.RequestHandler.sendRequest(RequestHandler.java:120)
	at com.datastax.driver.core.SessionManager.execute(SessionManager.java:700)
	at com.datastax.driver.core.SessionManager.executeAsync(SessionManager.java:144)
	at akka.persistence.cassandra.session.scaladsl.CassandraSession$SelectSource$$anon$2.$anonfun$preStart$4(CassandraSession.scala:424)
	at scala.concurrent.Future.$anonfun$flatMap$1(Future.scala:303)
	at scala.concurrent.impl.Promise.$anonfun$transformWith$1(Promise.scala:37)
	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:92)
	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:92)
	... 4 more

09/06 12:13:46 ERROR[main] o.a.c.s.StartupChecks - cassandra.jmx.local.port missing from cassandra-env.sh, unable to start local JMX service.
12:13:48.244 [warn] com.lightbend.lagom.internal.scaladsl.registry.ScalaServiceRegistryClient [] - Service registry replied with an error when looking up serviceName=[kafka_native]
java.net.ConnectException: Connection refused: /127.0.0.1:9008
	at play.shaded.ahc.org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:179)
	at play.shaded.ahc.org.asynchttpclient.netty.channel.NettyChannelConnector$1.onFailure(NettyChannelConnector.java:108)
	at play.shaded.ahc.org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:28)
	at play.shaded.ahc.org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:20)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:327)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:343)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:632)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
	at play.shaded.ahc.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at play.shaded.ahc.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)
Caused by: play.shaded.ahc.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /127.0.0.1:9008
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
	at play.shaded.ahc.io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:327)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340)
	... 7 common frames omitted
Caused by: java.net.ConnectException: Connection refused
	... 11 common frames omitted
12:13:48.245 [error] akka.actor.OneForOneStrategy [sourceThread=user-impl-application-akka.actor.default-dispatcher-4, akkaTimestamp=10:13:48.245UTC, akkaSource=akka://user-impl-application/system/sharding/kafkaProducer-userTopic/com.nagravision.appuser.impl.UserEvent0/com.nagravision.appuser.impl.UserEvent0/producer, sourceActorSystem=user-impl-application] - Connection refused: /127.0.0.1:9008
java.net.ConnectException: Connection refused: /127.0.0.1:9008
	at play.shaded.ahc.org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:179)
	at play.shaded.ahc.org.asynchttpclient.netty.channel.NettyChannelConnector$1.onFailure(NettyChannelConnector.java:108)
	at play.shaded.ahc.org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:28)
	at play.shaded.ahc.org.asynchttpclient.netty.SimpleChannelFutureListener.operationComplete(SimpleChannelFutureListener.java:20)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:511)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:504)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:483)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:424)
	at play.shaded.ahc.io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:121)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.fulfillConnectPromise(AbstractNioChannel.java:327)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:343)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:632)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496)
	at play.shaded.ahc.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
	at play.shaded.ahc.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at play.shaded.ahc.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)
Caused by: play.shaded.ahc.io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: /127.0.0.1:9008
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
	at play.shaded.ahc.io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:327)
	at play.shaded.ahc.io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340)
	... 7 common frames omitted
Caused by: java.net.ConnectException: Connection refused
	... 11 common frames omitted
2019-09-06 12:13:48,881 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task cassandraOffsetStorePrepare.
2019-09-06 12:13:48,906 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Executing cluster start task readSideGlobalPrepare-CountryEventProcessor.
2019-09-06 12:13:49,716 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task readSideGlobalPrepare-CountryEventProcessor done.
2019-09-06 12:13:49,738 INFO  com.lightbend.lagom.internal.persistence.cluster.ClusterStartupTaskActor - Cluster start task cassandraOffsetStorePrepare done.
[info] CountryServiceSpec:
[info] Country service
c Country(66,switzerland.gif,CH,Switzerland,EMEA)
2019-09-06 12:13:50,941 WARN  akka.serialization.Serialization(akka://country) - Using the default Java serializer for class [com.nagravision.country.impl.CountryCreated] which is not recommended because of performance implications. Use another serializer or disable this warning using the setting 'akka.actor.warn-about-java-serializer-usage'
[info] - should create country
2019-09-06 12:13:51,108 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
2019-09-06 12:13:51,109 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
2019-09-06 12:13:51,110 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
2019-09-06 12:13:51,110 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 1000 milliseconds
2019-09-06 12:13:51,120 WARN  akka.stream.scaladsl.RestartWithBackoffSource - Restarting graph due to failure. stack_trace: 
java.util.concurrent.ExecutionException: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (tried: /127.0.0.1:62715 (com.datastax.driver.core.exceptions.BusyPoolException: [/127.0.0.1] Pool is busy (no available connection and the queue has reached its max size 0)))
	at com.google.common.util.concurrent.AbstractFuture.getDoneValue(AbstractFuture.java:552)
	at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:513)
	at akka.persistence.cassandra.package$$anon$1.$anonfun$run$1(package.scala:18)
	at scala.util.Try$.apply(Try.scala:209)
	at akka.persistence.cassandra.package$$anon$1.run(package.scala:18)
	at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: com.datastax.driver.core.exceptions.NoHostAvailableException: All host(s) tried for query failed (tried: /127.0.0.1:62715 (com.datastax.driver.core.exceptions.BusyPoolException: [/127.0.0.1] Pool is busy (no available connection and the queue has reached its max size 0)))
	at com.datastax.driver.core.RequestHandler.reportNoMoreHosts(RequestHandler.java:265)
	at com.datastax.driver.core.RequestHandler.access$1200(RequestHandler.java:62)
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution.findNextHostAndQuery(RequestHandler.java:357)
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution$1.onFailure(RequestHandler.java:426)
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1070)
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30)
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1138)
	at com.google.common.util.concurrent.AbstractFuture.addListener(AbstractFuture.java:707)
	at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.addListener(AbstractFuture.java:112)
	at com.google.common.util.concurrent.Futures.addCallback(Futures.java:1051)
	at com.datastax.driver.core.GuavaCompatibility.addCallback(GuavaCompatibility.java:112)
	at com.datastax.driver.core.GuavaCompatibility.addCallback(GuavaCompatibility.java:100)
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution.query(RequestHandler.java:382)
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution.findNextHostAndQuery(RequestHandler.java:341)
	at com.datastax.driver.core.RequestHandler.startNewExecution(RequestHandler.java:138)
	at com.datastax.driver.core.RequestHandler.sendRequest(RequestHandler.java:120)
	at com.datastax.driver.core.SessionManager.execute(SessionManager.java:700)
	at com.datastax.driver.core.SessionManager.executeAsync(SessionManager.java:144)
	at akka.persistence.cassandra.query.EventsByTagFetcher.preStart(EventsByTagFetcher.scala:86)
	at akka.actor.Actor.aroundPreStart(Actor.scala:550)
	at akka.actor.Actor.aroundPreStart$(Actor.scala:550)
	at akka.persistence.cassandra.query.EventsByTagFetcher.aroundPreStart(EventsByTagFetcher.scala:50)
	at akka.actor.ActorCell.create(ActorCell.scala:674)
	at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:545)
	at akka.actor.ActorCell.systemInvoke(ActorCell.scala:567)
	at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:293)
	at akka.dispatch.Mailbox.run(Mailbox.scala:228)
	... 3 more

2019-09-06 12:13:52,111 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 2000 milliseconds
2019-09-06 12:13:52,112 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 2000 milliseconds
2019-09-06 12:13:52,113 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 2000 milliseconds
2019-09-06 12:13:52,114 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 2000 milliseconds
2019-09-06 12:13:54,113 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 4000 milliseconds
2019-09-06 12:13:54,113 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 4000 milliseconds
2019-09-06 12:13:54,114 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 4000 milliseconds
2019-09-06 12:13:54,117 ERROR com.datastax.driver.core.ControlConnection - [Control connection] Cannot connect to any host, scheduling retry in 4000 milliseconds
[info] Run completed in 11 seconds, 841 milliseconds.
[info] Total number of tests run: 2
[info] Suites: completed 2, aborted 0
[info] Tests: succeeded 2, failed 0, canceled 0, ignored 0, pending 0
[info] All tests passed.
12:13:56.403 [warn] akka.cluster.Cluster(akka://user-impl-application) [sourceThread=user-impl-application-akka.actor.default-dispatcher-2, akkaTimestamp=10:13:56.403UTC, akkaSource=akka.cluster.Cluster(akka://user-impl-application), sourceActorSystem=user-impl-application] - Cluster Node [akka.tcp://user-impl-application@127.0.0.1:55801] - Scheduled sending of heartbeat was delayed. Previous heartbeat was sent [2209] ms ago, expected interval is [1000] ms. This may cause failure detection to mark members as unreachable. The reason can be thread starvation, e.g. by running blocking tasks on the default dispatcher, CPU overload, or GC.
[success] Total time: 15 s, completed Sep 6, 2019 12:13:57 PM
6

I think there are some timing issues where the service can try to connect to the database before it’s fully available. It automatically retries, and it looks like your tests are passing, so I think you can treat this as harmless noise in the logs. There’s an open issue to improve this https://github.com/lagom/lagom/issues/1597.