How to debug actor timeout reactivemongo api cursor fails to send request logback hell

Question

Scala Play app with reactive mongo akka actors

sbt run:

I occasionaly get this error like ten times on sbt console:

It usually happens after a recompile and play reload, otherwise it happens less often, it doesn't cause anything to fail, sometimes page gives error.

[error] r.api.Cursor - fails to send request
java.util.concurrent.TimeoutException: Futures timed out after [3000 milliseconds]
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219) ~[scala-library-2.11.7.jar:na]
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:153) ~[scala-library-2.11.7.jar:na]
        at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169) ~[scala-library-2.11.7.jar:na]
        at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169) ~[scala-library-2.11.7.jar:na]
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:169) ~[akka-actor_2.11-2.3.13.jar:na]
        at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java:3640) [scala-library-2.11.7.jar:na]
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:167) ~[akka-actor_2.11-2.3.13.jar:na]
        at scala.concurrent.Await$.ready(package.scala:169) ~[scala-library-2.11.7.jar:na]
        at reactivemongo.api.DefaultCursor$Impl$$anonfun$awaitFailover$1.apply(cursor.scala:474) ~[reactivemongo_2.11-0.11.10.jar:0.11.10]
        at reactivemongo.api.DefaultCursor$Impl$$anonfun$awaitFailover$1.apply(cursor.scala:474) ~[reactivemongo_2.11-0.11.10.jar:0.11.10]

Also When I start the app (connect to reactivemongo driver mongodb) I get this output:

[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The node set is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated
[info] r.c.actors.MongoDBSystem - The primary is now authenticated

why so much? how do i debug this kind of stuff.

Edit:

I connect to mongolab.com mongodb so i tried this:

val defaultStrategy = FailoverStrategy()

val customStrategy =
  FailoverStrategy(
    delayFactor = attempt => 10
  )

// database-wide strategy
val db = connection.db("dbname", customStrategy)

but i saw a timeout of 10500! network is fine, omg what is wrong with this reactivemongo?

I have this:

val RM = "org.reactivemongo" %% "reactivemongo" % "0.11.10"
val PRM = "org.reactivemongo" %% "play2-reactivemongo" % "0.11.10"

What does this error mean (it doesn't crash the app or anything why), and what kind of code causes this?

I have the same problem, which I could steadily reproduce in testing. Reactivemongo just released 0.11.11 and it does not happen for me anymore, but it became too slow, so I just increased number of retries & delay and went back to 0.11.10 — mavarazy, Apr 06 '16 at 20:36

mavarazy · Answer 1 · 2016-04-06T22:02:17.330

I have the same problem, which I could steadily reproduce while testing.

I tried switching to Reactivemongo fresh release 0.11.11 the exception stopped, so as whole system performance went down.

My final solution is - increase number of connections, and change failover strategy

    val mongoDriver = new MongoDriver(Some(configuration.underlying))
    Runtime.getRuntime().addShutdownHook(new Thread() {
        override def run() = {
            mongoDriver.close()
        }
    })

    val connectionOptions = MongoConnectionOptions(
        nbChannelsPerNode = 40,
        connectTimeoutMS = 5000
    )
    val mongoConnection: MongoConnection = mongoDriver.connection(List(mongoHost), connectionOptions)
    val customStrategy = FailoverStrategy(
        retries = 8,
        delayFactor = n => n * 1.5
    )
    mongoConnection(mongoDB, customStrategy)

Now I don't see them, or they are harder to reproduce.

How to debug actor timeout reactivemongo api cursor fails to send request logback hell

Edit:

1 Answers1