Always [warn]...PrimaryUnavailableException$: MongoError['No primary node is available!'] on startup

Robert Kuhar

unread,

Jun 19, 2013, 6:01:36 PM6/19/13

to reacti...@googlegroups.com

I'm trying to get started in Play 2.1-Scala with the ReactiveMongo driver. To this end I cloned the repo at https://github.com/sgodbillon/reactivemongo-demo-app and set to running it in my environment.

Configuring the conf/application.conf to look to my replset like...

# Simple configuration (by URI)

# The URI syntax supports the following format: mongodb://[username:password@]host1[:port1][,hostN[:portN]]/dbName

mongodb.uri = "mongodb://bobk-mbp.local:27017,bobk-mbp.local:27018/reactivemongo_app"

and starting the app with "play run" I notice that there is always a stacktrace at start time that suggests my replset has and issue, although the application seems to run fine. Running a plain-jane mongo shell shows that the replset is fine. What's up with this driver? Is my configuration confusing it? My intent is to give it a collection of replSetSeeds so if one is down or unreachable it goes to the next in the set and tries again. How do I express this use case in the application.conf?

Here's the what the logs say:

[debug] play - Plugin [play.api.cache.EhCachePlugin] is disabled

[info] application - ReactiveMongoPlugin starting...

[info] application - ReactiveMongoPlugin successfully started with db 'reactivemongo_app'! Servers:

[bobk-mbp.local:27017]

[bobk-mbp.local:27018]

[info] play - Application started (Dev)

[warn] r.api.Failover - Got an error, retrying... (try #1 is scheduled in 500 ms)

reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$: MongoError['No primary node is available!']

at reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$.<clinit>(actors.scala) ~[reactivemongo_2.10-0.9.jar:0.9]

at reactivemongo.core.actors.MongoDBSystem$$anonfun$pickChannel$5.apply(actors.scala:385) ~[reactivemongo_2.10-0.9.jar:0.9]

at scala.Option.toRight(Option.scala:280) ~[scala-library.jar:na]

at reactivemongo.core.actors.MongoDBSystem.pickChannel(actors.scala:385) ~[reactivemongo_2.10-0.9.jar:0.9]

at reactivemongo.core.actors.MongoDBSystem$$anonfun$receive$1.applyOrElse(actors.scala:154) ~[reactivemongo_2.10-0.9.jar:0.9]

[info] a.e.s.Slf4jEventHandler - Slf4jEventHandler started

[debug] play - java.nio.channels.ClosedChannelException

[info] application - Checked index, result is Success(true)

Bob

Robert Kuhar

unread,

Jun 20, 2013, 9:16:05 PM6/20/13

to reacti...@googlegroups.com

The silence is deafening here. Am I alone at seeing this issue? Nothing here, nothing on StackOverflow. And then...depression set in?

Alex Jarvis

unread,

Jun 21, 2013, 4:18:41 AM6/21/13

to reacti...@googlegroups.com

Hi Robert,

So the case you are experiencing is normal behaviour - I think there was some discussion a while back although it's hard to remember the details.

For my application.conf I have added "logger.reactivemongo=ERROR" - as the error is only a warn, not an error and it occurs whilst the plugin is obtaining a socket or something like that.

I don't think this is anything to do with replica sets - it also occurs with just one node on localhost even.

I hope this breaks the silence on this issue, although you may want a more concrete explanation. Anyone?

Cheers,
Alex

Robert Kuhar

unread,

Jun 21, 2013, 10:40:15 AM6/21/13

to reacti...@googlegroups.com

Thanks for the reply. The silence is broken and my outlook improved. The false-positive warn is truly unnerving but I guess I can live with it. This feels like a bug to me but I've not gone into the code in search of truth. Thanks again.

Bob

Stephane Godbillon

unread,

Jun 26, 2013, 6:38:05 AM6/26/13

to reacti...@googlegroups.com

Yes it is something that should be fixed even if it is no more than a startup warning.

-- Stephane Godbillon

Blog: http://stephane.godbillon.com

Twitter: https://twitter.com/sgodbillon

Github: https://github.com/sgodbillon

2013/6/21 Robert Kuhar <rober...@gmail.com>

--
You received this message because you are subscribed to the Google Groups "ReactiveMongo - http://reactivemongo.org" group.
To unsubscribe from this group and stop receiving emails from it, send an email to reactivemong...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

Robert Kuhar

unread,

Jun 26, 2013, 6:52:32 PM6/26/13

to reacti...@googlegroups.com

What really seems to be causing the [warns] isn't so much the initial start of the application, it is the reloads of the application when I'm doing development. What I am observing is that, if I'm in the console executing the "run" task, for any code I edit, the next request causes the application to stop and start. Its on these transitions that the "false positive" [warn]s are emitted, although the log suggests the plug-in is being shut down, maybe the plugin isn't cleaning up after itself? The problem gets worse the longer the "run" session goes on and the more compiles occur. The [warn]s become [error]s (and are still false positive, the replset is fine and the queries in my controllers will succeed).

Is there somewhere I could enter a proper bug report? I can repro this pretty much at will? Is it the plug-in? Is it the driver? Please advise. Here's a session that started out great, got the false positive [warn] on the first recompile, the [warn]s became [error]s on the 3rd and subsequent compiles. At all points, my controller was working like a champ.

[dm2-server] $ run

--- (Running the application from SBT, auto-reloading is enabled) ---

[info] play - Listening for HTTP on /0:0:0:0:0:0:0:0:9000

(Server started, use Ctrl+D to stop and go back to the console...)

[info] Compiling 2 Scala sources to /Users/bobk/work/dm2-server/target/scala-2.10/classes...

2013-06-26T15:41:37.511Z [info] application DSN: APV: RID: - ReactiveMongoPlugin starting...

2013-06-26T15:41:37.532Z [info] application DSN: APV: RID: - ReactiveMongoPlugin successfully started with db 'dm2'! Servers:

[bobk-mbp.local:27017]

[bobk-mbp.local:27018]

2013-06-26T15:41:37.534Z [info] application DSN: APV: RID: - dm2-server starting

2013-06-26T15:41:37.534Z [info] Global$ DSN: APV: RID: - dm2-server starting

2013-06-26T15:41:37.542Z [info] play DSN: APV: RID: - Application started (Dev)

2013-06-26T15:41:37.593Z [trace] c.a.Apps$ DSN: APV: RID: - constructor

2013-06-26T15:41:37.777Z [info] a.e.s.Slf4jEventHandler DSN: APV: RID: - Slf4jEventHandler started

2013-06-26T15:41:37.817Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps

2013-06-26T15:41:59.268Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps

2013-06-26T15:42:02.681Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps

2013-06-26T15:42:04.315Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps

[info] Compiling 1 Scala source to /Users/bobk/work/dm2-server/target/scala-2.10/classes...

--- (RELOAD) ---

2013-06-26T15:42:26.219Z [info] Global$ DSN: APV: RID: - dm2-server stopping

2013-06-26T15:42:26.220Z [info] application DSN: APV: RID: - dm2-server stopping

2013-06-26T15:42:26.221Z [info] application DSN: APV: RID: - ReactiveMongoPlugin stops, closing connections...

2013-06-26T15:42:26.252Z [info] application DSN: APV: RID: - ReactiveMongo Connections stopped. [Success(Closed)]

2013-06-26T15:42:26.326Z [info] application DSN: APV: RID: - ReactiveMongoPlugin starting...

2013-06-26T15:42:26.327Z [info] application DSN: APV: RID: - ReactiveMongoPlugin successfully started with db 'dm2'! Servers:

[bobk-mbp.local:27017]

[bobk-mbp.local:27018]

2013-06-26T15:42:26.328Z [info] application DSN: APV: RID: - dm2-server starting

2013-06-26T15:42:26.329Z [info] Global$ DSN: APV: RID: - dm2-server starting

2013-06-26T15:42:26.329Z [info] play DSN: APV: RID: - Application started (Dev)

2013-06-26T15:42:26.340Z [trace] c.a.Apps$ DSN: APV: RID: - constructor

2013-06-26T15:42:26.345Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps blah

2013-06-26T15:42:26.384Z [warn] r.a.Failover DSN: APV: RID: - Got an error, retrying... (try #1 is scheduled in 500 ms)

reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$: MongoError['No primary node is available!']

at reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$.<clinit>(actors.scala) ~[reactivemongo_2.10-0.9.jar:0.9]

at reactivemongo.core.actors.MongoDBSystem$$anonfun$pickChannel$5.apply(actors.scala:385) ~[reactivemongo_2.10-0.9.jar:0.9]

at scala.Option.toRight(Option.scala:280) ~[scala-library.jar:na]

at reactivemongo.core.actors.MongoDBSystem.pickChannel(actors.scala:385) ~[reactivemongo_2.10-0.9.jar:0.9]

at reactivemongo.core.actors.MongoDBSystem$$anonfun$receive$1.applyOrElse(actors.scala:154) ~[reactivemongo_2.10-0.9.jar:0.9]

at akka.actor.ActorCell.receiveMessage(ActorCell.scala:425) ~[akka-actor_2.10.jar:na]

at akka.actor.ActorCell.invoke(ActorCell.scala:386) ~[akka-actor_2.10.jar:na]

at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:230) ~[akka-actor_2.10.jar:na]

at akka.dispatch.Mailbox.run(Mailbox.scala:212) ~[akka-actor_2.10.jar:na]

at akka.dispatch.ForkJoinExecutorConfigurator$MailboxExecutionTask.exec(AbstractDispatcher.scala:502) ~[akka-actor_2.10.jar:na]

at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:262) [scala-library.jar:na]

at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:975) [scala-library.jar:na]

at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1478) [scala-library.jar:na]

at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:104) [scala-library.jar:na]

2013-06-26T15:42:42.468Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps blah

2013-06-26T15:42:43.522Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps blah

2013-06-26T15:42:46.517Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps blah

2013-06-26T15:42:49.017Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps blah

[info] Compiling 1 Scala source to /Users/bobk/work/dm2-server/target/scala-2.10/classes...

--- (RELOAD) ---

2013-06-26T15:46:39.206Z [info] Global$ DSN: APV: RID: - dm2-server stopping

2013-06-26T15:46:39.207Z [info] application DSN: APV: RID: - dm2-server stopping

2013-06-26T15:46:39.207Z [info] application DSN: APV: RID: - ReactiveMongoPlugin stops, closing connections...

2013-06-26T15:46:39.221Z [info] application DSN: APV: RID: - ReactiveMongo Connections stopped. [Success(Closed)]

2013-06-26T15:46:39.294Z [info] application DSN: APV: RID: - ReactiveMongoPlugin starting...

2013-06-26T15:46:39.295Z [info] application DSN: APV: RID: - ReactiveMongoPlugin successfully started with db 'dm2'! Servers:

[bobk-mbp.local:27017]

[bobk-mbp.local:27018]

2013-06-26T15:46:39.296Z [info] application DSN: APV: RID: - dm2-server starting

2013-06-26T15:46:39.296Z [info] Global$ DSN: APV: RID: - dm2-server starting

2013-06-26T15:46:39.296Z [info] play DSN: APV: RID: - Application started (Dev)

2013-06-26T15:46:39.307Z [trace] c.a.Apps$ DSN: APV: RID: - constructor

2013-06-26T15:46:39.313Z [trace] c.a.Apps$ DSN: APV: RID: - getAllApps

2013-06-26T15:46:39.339Z [warn] r.a.Failover DSN: APV: RID: - Got an error, retrying... (try #1 is scheduled in 500 ms)