ActorSystem is being created twice during dependency injection


(Roman Iakovlev) #1

Setting: Play 2.6.6 + Akka Cluster + Guice
I’m running into an issue where it seems a second attempt to create an ActorSystem is being made. I’m requesting for an instance of ActorSystem (to use Akka Streams), and I see a Guice error with a root cause of not being able to bind to a port on which my ActorSystem is listening. Before that happens I see a normal Play app startup sequence, where the first instance of ActorSystem starts and joins the cluster.

I’ve traced it down to one particular class (and accompanying Provider instance). The provider asks for an instance of ActorSystem and passes it to the new instance of class. Removing references to this class fixes the problem. I use the same pattern (injecting instance of ActorSystem) elsewhere, and it just works, but not in this particular case.

This is the code of the provider:

import javax.inject.{Inject, Named}

import akka.actor.ActorSystem
import akka.http.scaladsl.model.Uri
import com.google.inject.Provider

class HttpClientProvider @Inject()(system: ActorSystem,
                                     @Named("auth.endpoint") endpoint: String,
                                     @Named("auth.queue-size") queueSize: Int)
  extends Provider[QueuedHttpClient] {
  override def get(): QueuedHttpClient = {
    val uri = Uri(endpoint)
    new QueuedHttpClient(uri.authority, uri.scheme, system)
  }
}

(Marcos Pereira) #2

Hi, @RomanIakovlev.

Could you please also share the stack trace? What if you annotate HttpClientProvider as a @Singleton?


(Roman Iakovlev) #3

Hi @marcospereira,

Yes, here goes the whole startup sequence (packages and classes names are edited).

 2018-03-23 10:19:02,789 [info] a.e.s.Slf4jLogger - Slf4jLogger started
 2018-03-23 10:19:03,298 [info] a.r.Remoting - Starting remoting *** - first ActorSystem starts
 2018-03-23 10:19:03,529 [info] a.r.Remoting - Remoting started; listening on addresses :[akka.tcp://notifications-cluster@localhost:2551]
 2018-03-23 10:19:03,560 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Starting up...
 2018-03-23 10:19:03,643 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Registered cluster JMX MBean [akka:type=Cluster]
 2018-03-23 10:19:03,645 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Started up successfully
 2018-03-23 10:19:03,715 [info] d.h.c.Constructr - Creating constructr-machine, because no seed-nodes defined
 2018-03-23 10:19:03,744 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - No seed-nodes configured, manual cluster join required
 2018-03-23 10:19:03,887 [info] c.h.c.c.a.c.m.c.ClusterMan - Akka cluster management started.
 2018-03-23 10:19:04,011 [info] r.a.RedisClientActor - Connect to localhost/127.0.0.1:6379
 2018-03-23 10:19:04,026 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Metrics collection has started successfully
 2018-03-23 10:19:04,061 [info] a.a.ActorSystemImpl - HTTP cluster management started
 2018-03-23 10:19:04,154 [info] r.a.RedisClientActor - Connected to localhost/127.0.0.1:6379
 2018-03-23 10:19:04,306 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Node [akka.tcp://notifications-cluster@localhost:2551] is JOINING, roles [notifications-webapp, dc-default]
 2018-03-23 10:19:04,329 [info] a.c.Cluster(akka://notifications-cluster) - Cluster Node [akka.tcp://notifications-cluster@localhost:2551] - Leader is moving node [akka.tcp://notifications-cluster@localhost:2551] to [Up]
 2018-03-23 10:19:05,981 [info] a.c.s.ClusterSingletonManager - Singleton manager starting singleton actor [akka://notifications-cluster/user/scheduler-singleton/singleton]
 2018-03-23 10:19:05,984 [info] a.c.s.ClusterSingletonManager - ClusterSingletonManager state change [Start -> Oldest]
 2018-03-23 10:19:06,093 [info] r.a.RedisClientActor - Connect to localhost/127.0.0.1:6379
 2018-03-23 10:19:06,098 [info] r.a.RedisClientActor - Connected to localhost/127.0.0.1:6379
 2018-03-23 10:19:06,175 [info] r.a.RedisClientActor - Connect to localhost/127.0.0.1:6379
 2018-03-23 10:19:06,181 [info] r.a.RedisClientActor - Connected to localhost/127.0.0.1:6379
 2018-03-23 10:19:06,205 [info] c.h.a.d.a.n.w.a.ScheduleLeader - Receive RecoveryCompleted
 2018-03-23 10:19:06,205 [info] c.h.a.d.a.n.w.a.ScheduleLeader - start recovering schedule leader from database
[INFO] [03/23/2018 10:19:06.704] [netty-event-loop-2] [akka.remote.Remoting] Starting remoting *** - second ActorSystem attempts to start...
[ERROR] [03/23/2018 10:19:06.720] [default-akka.remote.default-remote-dispatcher-5] [NettyTransport(akka://default)] failed to bind to /0.0.0.0:2551, shutting down Netty transport *** - ... and fails to bind to a port
[INFO] [03/23/2018 10:19:06.761] [default-akka.remote.default-remote-dispatcher-5] [akka://default/system/remoting-terminator] Shutting down remote daemon.
[INFO] [03/23/2018 10:19:06.764] [default-akka.remote.default-remote-dispatcher-5] [akka://default/system/remoting-terminator] Remote daemon shut down; proceeding with flushing remote transports.
[ERROR] [03/23/2018 10:19:06.775] [default-akka.remote.default-remote-dispatcher-6] [akka.remote.Remoting] Remoting system has been terminated abrubtly. Attempting to shut down transports
[INFO] [03/23/2018 10:19:06.780] [default-akka.remote.default-remote-dispatcher-6] [akka://default/system/remoting-terminator] Remoting shut down.
 2018-03-23 10:19:06,825 [info] a.c.s.ClusterSingletonProxy - Singleton identified at [akka://notifications-cluster/user/scheduler-singleton/singleton]
 2018-03-23 10:19:06,826 [info] a.c.s.ClusterSingletonProxy - Singleton identified at [akka://notifications-cluster/user/scheduler-singleton/singleton]
 2018-03-23 10:19:06,953 [info] p.a.h.EnabledFilters - Enabled Filters (see <https://www.playframework.com/documentation/latest/Filters>):

    play.filters.gzip.GzipFilter

 2018-03-23 10:19:07,671 [error] application -

! @77c6dn1m3 - Internal server error, for (GET) [/version] ->

play.api.UnexpectedException: Unexpected exception[ProvisionException: Unable to provision, see the following errors:

1) Error in custom provider, org.jboss.netty.channel.ChannelException: Failed to bind to: /0.0.0.0:2551
  while locating com.example.utils.HttpClientProvider *** - this is the provider that causes creation of second ActorSystem, the source code for it is in the original message
  while locating com.example.utils.QueuedHttpClient annotated with @com.google.inject.name.Named(value=example-account-queued-client)
    for the 7th parameter of com.example.security.exampleaccount.AuthService.<init>(HereAccountAuthService.scala:26)
  while locating com.example.security.exampleaccount.AuthService
    for the 2nd parameter of com.example.security.TokenValidationService.<init>(TokenValidationService.scala:27)
  while locating com.example.security.TokenValidationService
    for the 1st parameter of com.example.security.AuthenticatedAction.<init>(AuthenticatedAction.scala:16)
  while locating com.example.security.AuthenticatedAction
  while locating play.api.mvc.ActionBuilder<com.example.security.AuthenticatedRequest, play.api.mvc.AnyContent> annotated with @com.google.inject.name.Named(value=authenticated.request.action.mbb)
    for the 1st parameter of com.example.utils.AuthenticationProvider.<init>(AuthenticationProvider.scala:11)
  while locating com.example.utils.AuthenticationProvider
  while locating play.api.mvc.ActionBuilder<com.example.security.AuthenticatedRequest, play.api.mvc.AnyContent> annotated with @com.google.inject.name.Named(value=authenticated.request.action)
    for the 1st parameter of com.example.notify.webapp.controllers.NotificationsController.<init>(NotificationsController.scala:20)
  while locating com.example.notify.webapp.controllers.NotificationsController
    for the 3rd parameter of router.Routes.<init>(Routes.scala:30)
  while locating router.Routes
  while locating play.api.inject.RoutesProvider
  while locating play.api.routing.Router
    for the 1st parameter of play.api.http.JavaCompatibleHttpRequestHandler.<init>(HttpRequestHandler.scala:222)
  while locating play.api.http.JavaCompatibleHttpRequestHandler
  while locating play.api.http.HttpRequestHandler
    for the 6th parameter of play.api.DefaultApplication.<init>(Application.scala:236)
  at play.api.DefaultApplication.class(Application.scala:235)
  while locating play.api.DefaultApplication
  while locating play.api.Application

1 error]
    at play.core.server.DevServerStart$$anon$1.reload(DevServerStart.scala:186)
    at play.core.server.DevServerStart$$anon$1.get(DevServerStart.scala:124)
    at play.core.server.netty.PlayRequestHandler.modelConversion(PlayRequestHandler.scala:70)
    at play.core.server.netty.PlayRequestHandler.handle(PlayRequestHandler.scala:81)
    at play.core.server.netty.PlayRequestHandler.channelRead(PlayRequestHandler.scala:184)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
    at com.typesafe.netty.http.HttpStreamsHandler.channelRead(HttpStreamsHandler.java:129)
    at com.typesafe.netty.http.HttpStreamsServerHandler.channelRead(HttpStreamsServerHandler.java:96)
Caused by: com.google.inject.ProvisionException: Unable to provision, see the following errors:

1) Error in custom provider, org.jboss.netty.channel.ChannelException: Failed to bind to: /0.0.0.0:2551
  while locating com.example.utils.HttpClientProvider
  while locating com.example.utils.QueuedHttpClient annotated with @com.google.inject.name.Named(value=example-account-queued-client)
    for the 7th parameter of com.example.security.exampleaccount.AuthService.<init>(AuthService.scala:26)
  while locating com.example.security.exampleaccount.AuthService
    for the 2nd parameter of com.example.security.TokenValidationService.<init>(TokenValidationService.scala:27)
  while locating com.example.security.TokenValidationService
    for the 1st parameter of com.example.security.AuthenticatedAction.<init>(AuthenticatedAction.scala:16)
  while locating com.example.security.AuthenticatedAction
  while locating play.api.mvc.ActionBuilder<com.example.security.AuthenticatedRequest, play.api.mvc.AnyContent> annotated with @com.google.inject.name.Named(value=authenticated.request.action.mbb)
    for the 1st parameter of com.example.utils.AuthenticationProvider.<init>(AuthenticationProvider.scala:11)
  while locating com.example.utils.AuthenticationProvider
  while locating play.api.mvc.ActionBuilder<com.example.security.AuthenticatedRequest, play.api.mvc.AnyContent> annotated with @com.google.inject.name.Named(value=authenticated.request.action)
    for the 1st parameter of com.example.notify.webapp.controllers.NotificationsController.<init>(NotificationsController.scala:20)
  while locating com.example.notify.webapp.controllers.NotificationsController
    for the 3rd parameter of router.Routes.<init>(Routes.scala:30)
  while locating router.Routes
  while locating play.api.inject.RoutesProvider
  while locating play.api.routing.Router
    for the 1st parameter of play.api.http.JavaCompatibleHttpRequestHandler.<init>(HttpRequestHandler.scala:222)
  while locating play.api.http.JavaCompatibleHttpRequestHandler
  while locating play.api.http.HttpRequestHandler
    for the 6th parameter of play.api.DefaultApplication.<init>(Application.scala:236)
  at play.api.DefaultApplication.class(Application.scala:235)
  while locating play.api.DefaultApplication
  while locating play.api.Application

1 error
    at com.google.inject.internal.InjectorImpl$2.get(InjectorImpl.java:1028)
    at com.google.inject.internal.InjectorImpl.getInstance(InjectorImpl.java:1054)
    at play.api.inject.guice.GuiceInjector.instanceOf(GuiceInjectorBuilder.scala:409)
    at play.api.inject.guice.GuiceInjector.instanceOf(GuiceInjectorBuilder.scala:404)
    at play.api.inject.ContextClassLoaderInjector.$anonfun$instanceOf$2(Injector.scala:117)
    at play.api.inject.ContextClassLoaderInjector.withContext(Injector.scala:126)
    at play.api.inject.ContextClassLoaderInjector.instanceOf(Injector.scala:117)
    at play.api.inject.guice.GuiceApplicationBuilder.build(GuiceApplicationBuilder.scala:137)
    at play.api.inject.guice.GuiceApplicationLoader.load(GuiceApplicationLoader.scala:21)
    at play.core.server.DevServerStart$$anon$1.$anonfun$reload$3(DevServerStart.scala:174)
Caused by: org.jboss.netty.channel.ChannelException: Failed to bind to: /0.0.0.0:2551
    at org.jboss.netty.bootstrap.ServerBootstrap.bind(ServerBootstrap.java:272)
    at akka.remote.transport.netty.NettyTransport.$anonfun$listen$1(NettyTransport.scala:417)
    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 akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55)
    at akka.dispatch.BatchingExecutor$BlockableBatch.$anonfun$run$1(BatchingExecutor.scala:91)
Caused by: java.net.BindException: Address already in use
    at sun.nio.ch.Net.bind0(Native Method)
    at sun.nio.ch.Net.bind(Net.java:433)
    at sun.nio.ch.Net.bind(Net.java:425)
    at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)
    at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)
    at org.jboss.netty.channel.socket.nio.NioServerBoss$RegisterTask.run(NioServerBoss.java:193)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQueue(AbstractNioSelector.java:391)
    at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:315)
    at org.jboss.netty.channel.socket.nio.NioServerBoss.run(NioServerBoss.java:42)
    at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)

I know it’s a lot of text, so I’ve marked important entries in the text with *** marker and left some comments there. Basically, you see the second ActorSystem starts (interestingly, it uses different log format) when an attempt to create HttpClientProvider is made.

P.S. Switching to @Singleton haven’t helped, because the failure happens on the first instantiation of that provider.