search

lagom / lagom-samples

https://developer.lightbend.com/start/?group=lagom
Creative Commons Zero v1.0 Universal
86 stars 82 forks source link

ShoppingCart Java tests throwing exception even when tests are successfull #121

Closed marcospereira closed 4 years ago

marcospereira commented 5 years ago

For example:

https://travis-ci.com/lagom/lagom-samples/jobs/251610682#L1512-L1586

This happens for the test using TestServer with defaultSetup().withJdbc():

2019-10-31 20:43:32,013 INFO  com.zaxxer.hikari.HikariDataSource - HikariPool-2 - Shutdown completed.
2019-10-31 20:43:32,013 INFO  play.api.db.HikariCPConnectionPool - Shutting down connection pool.
2019-10-31 20:43:32,836 WARN  slick.basic.BasicBackend.stream - Error scheduling synchronous streaming
java.util.concurrent.RejectedExecutionException: Task slick.basic.BasicBackend$DatabaseDef$$anon$4@258ceb2 rejected from slick.util.AsyncExecutor$$anon$1$$anon$2@7c123a79[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 71]
    at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
    at slick.util.AsyncExecutor$$anon$1$$anon$4.execute(AsyncExecutor.scala:161)
    at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming(BasicBackend.scala:302)
    at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming$(BasicBackend.scala:300)
    at slick.jdbc.JdbcBackend$DatabaseDef.scheduleSynchronousStreaming(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction(BasicBackend.scala:295)
    at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction$(BasicBackend.scala:293)
    at slick.jdbc.JdbcBackend$DatabaseDef.streamSynchronousDatabaseAction(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef.slick$basic$BasicBackend$DatabaseDef$$runInContextInline(BasicBackend.scala:240)
    at slick.basic.BasicBackend$DatabaseDef.runInContextSafe(BasicBackend.scala:148)
    at slick.basic.BasicBackend$DatabaseDef.runInContext(BasicBackend.scala:142)
    at slick.basic.BasicBackend$DatabaseDef.runInContext$(BasicBackend.scala:141)
    at slick.jdbc.JdbcBackend$DatabaseDef.runInContext(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef$$anon$1.subscribe(BasicBackend.scala:118)
    at akka.stream.impl.fusing.ActorGraphInterpreter$BatchingActorInputBoundary.preStart(ActorGraphInterpreter.scala:134)
    at akka.stream.impl.fusing.GraphInterpreter.init(GraphInterpreter.scala:306)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:593)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:701)
    at akka.stream.impl.fusing.ActorGraphInterpreter.preStart(ActorGraphInterpreter.scala:750)
    at akka.actor.Actor.aroundPreStart(Actor.scala:543)
    at akka.actor.Actor.aroundPreStart$(Actor.scala:543)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundPreStart(ActorGraphInterpreter.scala:690)
    at akka.actor.ActorCell.create(ActorCell.scala:637)
    at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:509)
    at akka.actor.ActorCell.systemInvoke(ActorCell.scala:531)
    at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:294)
    at akka.dispatch.Mailbox.run(Mailbox.scala:229)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:242)
    at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
    at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
    at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
    at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
2019-10-31 20:43:32,846 WARN  slick.basic.BasicBackend.stream - Error scheduling synchronous streaming
java.util.concurrent.RejectedExecutionException: Task slick.basic.BasicBackend$DatabaseDef$$anon$4@22f716e0 rejected from slick.util.AsyncExecutor$$anon$1$$anon$2@7c123a79[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 71]
    at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
    at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
    at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
    at slick.util.AsyncExecutor$$anon$1$$anon$4.execute(AsyncExecutor.scala:161)
    at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming(BasicBackend.scala:302)
    at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming$(BasicBackend.scala:300)
    at slick.jdbc.JdbcBackend$DatabaseDef.scheduleSynchronousStreaming(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction(BasicBackend.scala:295)
    at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction$(BasicBackend.scala:293)
    at slick.jdbc.JdbcBackend$DatabaseDef.streamSynchronousDatabaseAction(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef.slick$basic$BasicBackend$DatabaseDef$$runInContextInline(BasicBackend.scala:240)
    at slick.basic.BasicBackend$DatabaseDef.runInContextSafe(BasicBackend.scala:148)
    at slick.basic.BasicBackend$DatabaseDef.runInContext(BasicBackend.scala:142)
    at slick.basic.BasicBackend$DatabaseDef.runInContext$(BasicBackend.scala:141)
    at slick.jdbc.JdbcBackend$DatabaseDef.runInContext(JdbcBackend.scala:37)
    at slick.basic.BasicBackend$DatabaseDef$$anon$1.subscribe(BasicBackend.scala:118)
    at akka.stream.impl.fusing.ActorGraphInterpreter$BatchingActorInputBoundary.preStart(ActorGraphInterpreter.scala:134)
    at akka.stream.impl.fusing.GraphInterpreter.init(GraphInterpreter.scala:306)
    at akka.stream.impl.fusing.GraphInterpreterShell.init(ActorGraphInterpreter.scala:593)
    at akka.stream.impl.fusing.ActorGraphInterpreter.tryInit(ActorGraphInterpreter.scala:701)
    at akka.stream.impl.fusing.ActorGraphInterpreter.preStart(ActorGraphInterpreter.scala:750)
    at akka.actor.Actor.aroundPreStart(Actor.scala:543)
    at akka.actor.Actor.aroundPreStart$(Actor.scala:543)
    at akka.stream.impl.fusing.ActorGraphInterpreter.aroundPreStart(ActorGraphInterpreter.scala:690)
    at akka.actor.ActorCell.create(ActorCell.scala:637)
    at akka.actor.ActorCell.invokeAll$1(ActorCell.scala:509)
    at akka.actor.ActorCell.systemInvoke(ActorCell.scala:531)
    at akka.dispatch.Mailbox.processAllSystemMessages(Mailbox.scala:294)
    at akka.dispatch.Mailbox.run(Mailbox.scala:229)
    at akka.dispatch.Mailbox.exec(Mailbox.scala:242)
    at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
    at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
    at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
    at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:157)
ignasi35 commented 5 years ago

I think the problem is CoordinatedShutdown closes the ProjectionWorker after the thread pool for Slick tasks has been closed. Shutting down the ProjectionWorker too late allows the queryByTag to poll the DB (even if it was closed already).

What I'm seeing is that the queryByTag stream in the ProjectionWorker doesn't seem to be killed until the [cluster-exiting] phase where cluster singletons are killed. I think the ProjectionWorker simply gets a Stopped$ message and that's not handled in a nicely-enough way (?).

~The quick solution is to register a CoordinatedShutdown task to kill the stream early so that when the cluster-exiting phase arrives all the Slick backlog has completed. But I'm not 100% sure that's correct either, I suspect this issue is not only affecting shutdown but also any attempt to stop the ProjectionWorker during normal use, in which case killing the stream early is not enough.~

EDIT: I need to investigate a bit more and read the logs and the stack trace again. I think I got this backwards.

Relevant bits of a DEBUG-level log ``` 2019-11-05 18:28:56,605 DEBUG akka.actor.CoordinatedShutdown - Running CoordinatedShutdown with reason [ApplicationStoppedReason] 2019-11-05 18:28:56,605 DEBUG akka.actor.CoordinatedShutdown - Performing phase [before-service-unbind] with [1] tasks. 2019-11-05 18:28:56,606 DEBUG akka.actor.CoordinatedShutdown - Performing task [trace-server-stop-request] in CoordinatedShutdown phase [before-service-unbind] 2019-11-05 18:28:56,611 DEBUG akka.actor.CoordinatedShutdown - Performing phase [service-unbind] with [1] tasks. 2019-11-05 18:28:56,611 DEBUG akka.actor.CoordinatedShutdown - Performing task [akka-http-server-unbind] in CoordinatedShutdown phase [service-unbind] 2019-11-05 18:28:56,616 DEBUG akka.io.TcpListener - Unbinding endpoint /0:0:0:0:0:0:0:0:58336 2019-11-05 18:28:56,626 DEBUG akka.io.TcpListener - Unbound endpoint /0:0:0:0:0:0:0:0:58336, stopping listener 2019-11-05 18:28:56,626 DEBUG akka.actor.CoordinatedShutdown - Performing phase [service-requests-done] with [0] tasks 2019-11-05 18:28:56,626 DEBUG akka.actor.CoordinatedShutdown - Performing phase [service-stop] with [1] tasks. 2019-11-05 18:28:56,626 DEBUG akka.actor.CoordinatedShutdown - Performing task [application-lifecycle-stophook] in CoordinatedShutdown phase [service-stop] 2019-11-05 18:28:56,638 INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown initiated... 2019-11-05 18:28:56,644 INFO com.zaxxer.hikari.HikariDataSource - HikariPool-1 - Shutdown completed. 2019-11-05 18:28:56,671 INFO play.api.db.HikariCPConnectionPool - Shutting down connection pool. 2019-11-05 18:28:56,674 DEBUG akka.actor.CoordinatedShutdown - Performing phase [before-cluster-shutdown] with [0] tasks 2019-11-05 18:28:56,675 DEBUG akka.actor.CoordinatedShutdown - Performing phase [cluster-sharding-shutdown-region] with [2] tasks. 2019-11-05 18:28:56,675 DEBUG akka.actor.CoordinatedShutdown - Performing task [region-shutdown] in CoordinatedShutdown phase [cluster-sharding-shutdown-region] 2019-11-05 18:28:56,677 DEBUG akka.cluster.sharding.ShardRegion - ShoppingCartReportProcessor: Starting graceful shutdown of region and all its shards 2019-11-05 18:28:56,677 DEBUG akka.actor.CoordinatedShutdown - Performing task [region-shutdown] in CoordinatedShutdown phase [cluster-sharding-shutdown-region] 2019-11-05 18:28:56,677 DEBUG akka.cluster.sharding.ShardRegion - ShoppingCartEntity: Starting graceful shutdown of region and all its shards 2019-11-05 18:28:56,681 DEBUG akka.cluster.sharding.DDataShardCoordinator - Graceful shutdown of region [Actor[akka://ServiceTest_191105182844699/system/sharding/ShoppingCartReportProcessor#-1964029288]] with shards [Vector(com.example.shoppingcart.impl.ShoppingCart$Event3, com.example.shoppingcart.impl.ShoppingCart$Event6, com.example.shoppingcart.impl.ShoppingCart$Event8, com.example.shoppingcart.impl.ShoppingCart$Event7, com.example.shoppingcart.impl.ShoppingCart$Event0, com.example.shoppingcart.impl.ShoppingCart$Event4, com.example.shoppingcart.impl.ShoppingCart$Event1, com.example.shoppingcart.impl.ShoppingCart$Event5, com.example.shoppingcart.impl.ShoppingCart$Event2, com.example.shoppingcart.impl.ShoppingCart$Event9)] ... 2019-11-05 18:28:56,730 DEBUG akka.cluster.sharding.DDataShardCoordinator - The coordinator state was successfully updated with ShardRegionTerminated(Actor[akka://ServiceTest_191105182844699/system/sharding/ShoppingCartEntity#1635504420]) 2019-11-05 18:28:56,731 DEBUG akka.cluster.sharding.DDataShardCoordinator - New coordinator state after [ShardRegionTerminated(Actor[akka://ServiceTest_191105182844699/system/sharding/ShoppingCartEntity#1635504420])]: [State(HashMap())] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing phase [cluster-exiting] with [16] tasks. 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-singleton-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-1] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-1] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-singleton-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-2] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-1] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-1] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-singleton-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-singleton-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-2] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,736 DEBUG akka.actor.CoordinatedShutdown - Performing task [wait-singleton-exiting] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,737 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-2] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,737 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-1] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,737 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-2] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,737 DEBUG akka.actor.CoordinatedShutdown - Performing task [singleton-exiting-2] in CoordinatedShutdown phase [cluster-exiting] 2019-11-05 18:28:56,743 INFO akka.cluster.singleton.ClusterSingletonManager - Exited [akka://ServiceTest_191105182844699@127.0.0.1:58332] 2019-11-05 18:28:56,745 INFO akka.cluster.singleton.ClusterSingletonManager - Exited [akka://ServiceTest_191105182844699@127.0.0.1:58332] 2019-11-05 18:28:56,745 INFO akka.cluster.singleton.ClusterSingletonManager - Exited [akka://ServiceTest_191105182844699@127.0.0.1:58332] 2019-11-05 18:28:56,745 INFO akka.cluster.singleton.ClusterSingletonManager - Exited [akka://ServiceTest_191105182844699@127.0.0.1:58332] 2019-11-05 18:28:56,747 INFO akka.cluster.singleton.ClusterSingletonManager - Oldest observed OldestChanged: [akka://ServiceTest_191105182844699@127.0.0.1:58332 -> None] 2019-11-05 18:28:56,747 INFO akka.cluster.singleton.ClusterSingletonManager - Oldest observed OldestChanged: [akka://ServiceTest_191105182844699@127.0.0.1:58332 -> None] 2019-11-05 18:28:56,766 INFO akka.cluster.singleton.ClusterSingletonManager - Oldest observed OldestChanged: [akka://ServiceTest_191105182844699@127.0.0.1:58332 -> None] 2019-11-05 18:28:56,799 INFO akka.cluster.singleton.ClusterSingletonManager - ClusterSingletonManager state change [Oldest -> WasOldest] 2019-11-05 18:28:56,799 INFO akka.cluster.singleton.ClusterSingletonManager - ClusterSingletonManager state change [Oldest -> WasOldest] 2019-11-05 18:28:56,800 INFO akka.cluster.singleton.ClusterSingletonManager - ClusterSingletonManager state change [Oldest -> WasOldest] 2019-11-05 18:28:56,804 INFO akka.cluster.singleton.ClusterSingletonManager - Exited [akka://ServiceTest_191105182844699@127.0.0.1:58332] 2019-11-05 18:28:56,804 INFO akka.cluster.singleton.ClusterSingletonManager - Oldest observed OldestChanged: [akka://ServiceTest_191105182844699@127.0.0.1:58332 -> None] 2019-11-05 18:28:56,804 INFO akka.cluster.singleton.ClusterSingletonManager - Oldest observed OldestChanged: [akka://ServiceTest_191105182844699@127.0.0.1:58332 -> None] 2019-11-05 18:28:56,805 INFO akka.cluster.singleton.ClusterSingletonManager - ClusterSingletonManager state change [Oldest -> WasOldest] 2019-11-05 18:28:56,805 INFO akka.cluster.singleton.ClusterSingletonManager - ClusterSingletonManager state change [Oldest -> WasOldest] 2019-11-05 18:28:56,807 DEBUG akka.serialization.Serialization(akka://ServiceTest_191105182844699) - Using serializer [com.lightbend.lagom.internal.projection.ProjectionMessageSerializer] for message [com.lightbend.lagom.internal.projection.ProjectionRegistryActor$WorkerCoordinates] 2019-11-05 18:28:56,824 DEBUG akka.serialization.Serialization(akka://ServiceTest_191105182844699) - Using serializer [com.lightbend.lagom.internal.projection.ProjectionMessageSerializer] for message [com.lightbend.lagom.projection.Started$] 2019-11-05 18:28:56,945 DEBUG akka.serialization.Serialization(akka://ServiceTest_191105182844699) - Using serializer [com.lightbend.lagom.internal.projection.ProjectionMessageSerializer] for message [com.lightbend.lagom.projection.Stopped$] 2019-11-05 18:28:56,950 WARN slick.basic.BasicBackend.stream - Error scheduling synchronous streaming java.util.concurrent.RejectedExecutionException: Task slick.basic.BasicBackend$DatabaseDef$$anon$4@1c4a6fdd rejected from slick.util.AsyncExecutor$$anon$1$$anon$2@6b9f8295[Terminated, pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 68] | => sat java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063) at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379) at slick.util.AsyncExecutor$$anon$1$$anon$4.execute(AsyncExecutor.scala:161) at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming(BasicBackend.scala:302) at slick.basic.BasicBackend$DatabaseDef.scheduleSynchronousStreaming$(BasicBackend.scala:300) at slick.jdbc.JdbcBackend$DatabaseDef.scheduleSynchronousStreaming(JdbcBackend.scala:37) at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction(BasicBackend.scala:295) at slick.basic.BasicBackend$DatabaseDef.streamSynchronousDatabaseAction$(BasicBackend.scala:293) at slick.jdbc.JdbcBackend$DatabaseDef.streamSynchronousDatabaseAction(JdbcBackend.scala:37) at slick.basic.BasicBackend$DatabaseDef.slick$basic$BasicBackend$DatabaseDef$$runInContextInline(BasicBackend.scala:240) at slick.basic.BasicBackend$DatabaseDef.runInContextSafe(BasicBackend.scala:148) at slick.basic.BasicBackend$DatabaseDef.runInContext(BasicBackend.scala:142) at slick.basic.BasicBackend$DatabaseDef.runInContext$(BasicBackend.scala:141) at slick.jdbc.JdbcBackend$DatabaseDef.runInContext(JdbcBackend.scala:37) at slick.basic.BasicBackend$DatabaseDef$$anon$1.subscribe(BasicBackend.scala:118) ```
marcospereira commented 5 years ago

Hum, so cluster-exiting phase happens before actor-system-terminate which is where the dispatchers are terminated as well (unless we are talking about a custom internal dispatcher and not one configured/provided by Akka): https://doc.akka.io/docs/akka/snapshot/coordinated-shutdown.html

I wonder if for tests we are misconfiguring terminate-actor-system and run-by-actor-system-terminate. 🤔

marcospereira commented 5 years ago

unless we are talking about a custom internal dispatcher and not one configured/provided by Akka

Yes, we are:

https://github.com/slick/slick/blob/16545a6954960e39c186a9ad146235cee4e4bb48/slick/src/main/scala/slick/util/AsyncExecutor.scala#L141-L200

And:

https://github.com/lagom/lagom/blob/5a1cd1a1e4ced11b562aabc8fafc823ada9586b7/persistence-jdbc/core/src/main/scala/com/lightbend/lagom/internal/persistence/jdbc/SlickDbProvider.scala#L56-L69

marcospereira commented 5 years ago

Where do we shutdown Slick? Is it still depends on ApplicationLifecycle? If so, in which phase of CS is ApplicationLifecycle.stop running? Stopping my (out of curiosity) investigation for now.

ignasi35 commented 5 years ago

Related: https://github.com/dnvriend/akka-persistence-jdbc/pull/193

ignasi35 commented 5 years ago

Where do we shutdown Slick? Is it still depends on ApplicationLifecycle? If so, in which phase of CS is ApplicationLifecycle.stop running? Stopping my (out of curiosity) investigation for now.

  1. where the ApplicationLifecycle stop hooks are invoked
  2. yes
  3. phase-service-stop

I'm not sure the question 1. ("Where do we shutdown Slick") is the right one though. The offending bit is a queryByTag implemented by akka-persistence-jdbc (aka APJDBC) and I must double check if APJDBC uses the DatabasedDef provided by Lagom's SlickDbProvider.

I just realised there are two Database's in play (no pun intended) on a ReadSideActor and it could be only one of them causing issues:

  1. the DB we read from using queryByTag
  2. the DB we read/write to for the read side (OffsetStore and user tables).
ignasi35 commented 5 years ago

I think there are some issues in Lagom:

  1. shutting down Slick from the ApplicationLifecycle stop hooks (which run on the service-stop phase of CoordinatedShutdown) is wrong. Being part of the infrastructure, anything related to accessing the database should be closed later.
  2. if users opt out from using the JNDI-provided DatabaseDef and, instead, use slick.db settings to create one, then the instance is not closed.

I think both are legit issues.

ignasi35 commented 5 years ago

I think both are legit issues.

After fixing those, I think we should also add a shutdown task for every projection worker to stop during the service-stop phase of CoordinatedShutdown. The reasoning is that a projection worker is producing traffic across de service (by means of polling the DB).

So putting it all together:

  1. service-stop finishes all ongoing work, including the projection streams (or even the worker itself)
  2. cluster-stop shuts down anything related to the cluster (including ShardRegion, sharded entities, etc..)
  3. system termination shuts down DB and other missing infrastructure.
ignasi35 commented 5 years ago

Oh, great. So after some cleanup for slick shutdown now the error is:

2019-11-06 14:50:31,084 DEBUG akka.actor.CoordinatedShutdown - Performing phase [before-cluster-shutdown] with [0] tasks
2019-11-06 14:50:31,085 DEBUG akka.actor.CoordinatedShutdown - Performing phase [cluster-sharding-shutdown-region] with [2] tasks.
2019-11-06 14:50:31,085 DEBUG akka.actor.CoordinatedShutdown - Performing task [region-shutdown] in CoordinatedShutdown phase [cluster-sharding-shutdown-region]
2019-11-06 14:50:31,107 DEBUG akka.cluster.sharding.ShardRegion - ShoppingCartReportProcessor: Starting graceful shutdown of region and all its shards
2019-11-06 14:50:31,108 WARN  akka.stream.scaladsl.RestartWithBackoffSource - Restarting graph due to failure. stack_trace: 
java.util.concurrent.CompletionException: java.lang.IllegalStateException: EntityManagerFactory is closed
        at java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:326)
        at java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:338)
        at java.util.concurrent.CompletableFuture.uniRelay(CompletableFuture.java:911)
        at java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:899)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)

java.util.concurrent.CompletionException: java.lang.IllegalStateException: EntityManagerFactory is closed 🙄🤦🏼‍♂️