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 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)
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 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:46:39.375Z [warn] r.c.a.MongoDBSystem DSN: APV: RID: - The primary is unavailable, is there a network problem?
2013-06-26T15:46:39.380Z [warn] r.c.a.MongoDBSystem DSN: APV: RID: - The primary is unavailable, is there a network problem?
2013-06-26T15:46:39.382Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.383Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.383Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.383Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.384Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.384Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.384Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.385Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.451Z [warn] r.c.a.MongoDBSystem DSN: APV: RID: - The primary is unavailable, is there a network problem?
2013-06-26T15:46:39.453Z [warn] r.c.a.MongoDBSystem DSN: APV: RID: - The primary is unavailable, is there a network problem?
2013-06-26T15:46:39.453Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.454Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.455Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.456Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.456Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?
2013-06-26T15:46:39.457Z [error] r.c.a.MongoDBSystem DSN: APV: RID: - The entire node set is unreachable, is there a network problem?