6

Very often, when Play reloads the application after a code change, I receive the following error:

MongoError['The node set can not be reached! Please check your network connectivity.']

The MongoDB log looks like this:

2016-09-06T18:51:22.609+0200 I NETWORK  [initandlisten] waiting for connections on port 27017
2016-09-06T18:53:49.916+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60559 #1 (1 connection now open)
2016-09-06T18:53:51.185+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60561 #2 (2 connections now open)
2016-09-06T18:53:51.196+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60562 #3 (3 connections now open)
2016-09-06T18:53:51.206+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60563 #4 (4 connections now open)
2016-09-06T18:53:51.217+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60564 #5 (5 connections now open)
2016-09-06T18:53:51.227+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60565 #6 (6 connections now open)
2016-09-06T18:53:51.237+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60566 #7 (7 connections now open)
2016-09-06T18:53:51.248+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60567 #8 (8 connections now open)
2016-09-06T18:53:51.258+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60568 #9 (9 connections now open)
2016-09-06T18:53:51.269+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60569 #10 (10 connections now open)
2016-09-06T18:53:59.533+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60577 #11 (11 connections now open)
2016-09-06T18:53:59.546+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60578 #12 (12 connections now open)
2016-09-06T18:53:59.557+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60579 #13 (13 connections now open)
2016-09-06T18:53:59.568+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60580 #14 (14 connections now open)
2016-09-06T18:53:59.579+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60581 #15 (15 connections now open)
2016-09-06T18:53:59.589+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60582 #16 (16 connections now open)
2016-09-06T18:53:59.600+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60583 #17 (17 connections now open)
2016-09-06T18:53:59.610+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60584 #18 (18 connections now open)
2016-09-06T18:53:59.620+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:60585 #19 (19 connections now open)
2016-09-06T19:37:21.594+0200 I NETWORK  [conn11] end connection 127.0.0.1:60577 (18 connections now open)
2016-09-06T19:37:21.596+0200 I NETWORK  [conn1] end connection 127.0.0.1:60559 (17 connections now open)
2016-09-06T19:37:21.597+0200 I NETWORK  [conn15] end connection 127.0.0.1:60581 (16 connections now open)
2016-09-06T19:37:21.597+0200 I NETWORK  [conn13] end connection 127.0.0.1:60579 (15 connections now open)
2016-09-06T19:37:21.597+0200 I NETWORK  [conn16] end connection 127.0.0.1:60582 (14 connections now open)
2016-09-06T19:37:21.598+0200 I NETWORK  [conn12] end connection 127.0.0.1:60578 (13 connections now open)
2016-09-06T19:37:21.598+0200 I NETWORK  [conn19] end connection 127.0.0.1:60585 (13 connections now open)
2016-09-06T19:37:21.599+0200 I NETWORK  [conn17] end connection 127.0.0.1:60583 (11 connections now open)
2016-09-06T19:37:21.599+0200 I NETWORK  [conn14] end connection 127.0.0.1:60580 (11 connections now open)
2016-09-06T19:37:21.600+0200 I NETWORK  [conn18] end connection 127.0.0.1:60584 (9 connections now open)
2016-09-06T19:37:21.607+0200 I NETWORK  [conn5] end connection 127.0.0.1:60564 (9 connections now open)
2016-09-06T19:37:21.607+0200 I NETWORK  [conn9] end connection 127.0.0.1:60568 (9 connections now open)
2016-09-06T19:37:21.608+0200 I NETWORK  [conn6] end connection 127.0.0.1:60565 (9 connections now open)
2016-09-06T19:37:21.608+0200 I NETWORK  [conn10] end connection 127.0.0.1:60569 (9 connections now open)
2016-09-06T19:37:21.609+0200 I NETWORK  [conn2] end connection 127.0.0.1:60561 (9 connections now open)
2016-09-06T19:37:21.609+0200 I NETWORK  [conn7] end connection 127.0.0.1:60566 (9 connections now open)
2016-09-06T19:37:21.610+0200 I NETWORK  [conn3] end connection 127.0.0.1:60562 (9 connections now open)
2016-09-06T19:37:21.611+0200 I NETWORK  [conn4] end connection 127.0.0.1:60563 (4 connections now open)
2016-09-06T19:37:21.612+0200 I NETWORK  [conn8] end connection 127.0.0.1:60567 (0 connections now open)
2016-09-06T19:37:22.326+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62077 #20 (1 connection now open)
2016-09-06T19:37:22.333+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62078 #21 (2 connections now open)
2016-09-06T19:37:22.333+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62079 #22 (3 connections now open)
2016-09-06T19:37:22.343+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62080 #23 (4 connections now open)
2016-09-06T19:37:22.344+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62081 #24 (5 connections now open)
2016-09-06T19:37:22.344+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62082 #25 (6 connections now open)
2016-09-06T19:37:22.344+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62083 #26 (7 connections now open)
2016-09-06T19:37:22.344+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62084 #27 (8 connections now open)
2016-09-06T19:37:22.354+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62085 #28 (9 connections now open)
2016-09-06T19:37:22.355+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62086 #29 (10 connections now open)
2016-09-06T19:37:32.348+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62105 #30 (11 connections now open)
2016-09-06T19:37:32.359+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62106 #31 (12 connections now open)
2016-09-06T19:37:32.393+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62107 #32 (13 connections now open)
2016-09-06T19:37:32.399+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62108 #33 (14 connections now open)
2016-09-06T19:37:32.399+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62109 #34 (15 connections now open)
2016-09-06T19:37:32.399+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62110 #35 (16 connections now open)
2016-09-06T19:37:32.399+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62111 #36 (17 connections now open)
2016-09-06T19:37:32.401+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62112 #37 (18 connections now open)
2016-09-06T19:37:32.401+0200 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:62113 #38 (19 connections now open)

Sometimes there's also this exception:

[warn] r.c.a.MongoDBSystem - The entire node set is unreachable, is there a network problem?
[warn] r.c.a.MongoDBSystem - The entire node set is unreachable, is there a network problem?
[error] r.api.Failover2 - Got an error, no more attempts to do. Completing with a failure...
reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$: MongoError['No primary node is available!']
        at reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$.<clinit>(actors.scala)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at scala.Option.getOrElse(Option.scala:121)
        at reactivemongo.core.actors.MongoDBSystem$class.reactivemongo$core$actors$MongoDBSystem$$pickChannel(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$4.applyOrElse(actors.scala:340)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170)
        at akka.actor.Actor$class.aroundReceive(Actor.scala:482)
        at reactivemongo.core.actors.LegacyDBSystem.aroundReceive(actors.scala:896)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
[error] r.api.Failover2 - Got an error, no more attempts to do. Completing with a failure...
reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$: MongoError['No primary node is available!']
        at reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$.<clinit>(actors.scala)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at scala.Option.getOrElse(Option.scala:121)
        at reactivemongo.core.actors.MongoDBSystem$class.reactivemongo$core$actors$MongoDBSystem$$pickChannel(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$4.applyOrElse(actors.scala:340)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170)
        at akka.actor.Actor$class.aroundReceive(Actor.scala:482)
        at reactivemongo.core.actors.LegacyDBSystem.aroundReceive(actors.scala:896)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
[error] r.api.Failover2 - Got an error, no more attempts to do. Completing with a failure...
reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$: MongoError['No primary node is available!']
        at reactivemongo.core.actors.Exceptions$PrimaryUnavailableException$.<clinit>(actors.scala)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$reactivemongo$core$actors$MongoDBSystem$$pickChannel$4.apply(actors.scala:748)
        at scala.Option.getOrElse(Option.scala:121)
        at reactivemongo.core.actors.MongoDBSystem$class.reactivemongo$core$actors$MongoDBSystem$$pickChannel(actors.scala:748)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$4.applyOrElse(actors.scala:340)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170)
        at akka.actor.Actor$class.aroundReceive(Actor.scala:482)
        at reactivemongo.core.actors.LegacyDBSystem.aroundReceive(actors.scala:896)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)

When I completely kill the process and execute activator run again, everything works like before.

Here's how I use ReactiveMongo:

val collection: Future[JSONCollection] = reactiveMongoApi.database.map(_.collection[JSONCollection](collectionName))

Used versions:

  • MongoDB: v3.2.4
  • Scala: 2.11.8
  • Play 2.5
  • play2-reactivemongo: 0.11.13
  • reactivemongo-play-json: 0.11.14

As developing like this takes forever, I would appreciate any help to fix this issue! :-)

John Doe
  • 277
  • 3
  • 14
  • Please indicate the used versions, and possibly test with latest versions is not already – cchantep Sep 06 '16 at 18:43
  • @cchantep Hi! I added all versions. – John Doe Sep 06 '16 at 18:53
  • Note that as indicated in the documentation, if you declare a dependency upon play2-reactivemongo, you should never add a separate dependency for reactivemongo-play-json (specially with different versions) – cchantep Sep 06 '16 at 22:49
  • Latest version is 0.12-RC3 – cchantep Sep 06 '16 at 22:52
  • @JohnDoe I get the same exception while running tests (restarting applications). – rethab Sep 07 '16 at 06:19
  • That error _No primary node_ sounds like it is dealing with a [replicaset](https://docs.mongodb.com/manual/replication/). Is that how your mongodb is configured? Or is it a single database server? – Vince Bowdren Sep 07 '16 at 08:25
  • No, I actually run MongoDB locally just for developing purposes. Everything is in default configuration. @cchantep What if I need both plugins? How do I go about this? Also, could it be that this issue occurs because I have multiple modules which have this two plugins declared as a dependency? – John Doe Sep 07 '16 at 13:29
  • @JohnDoe you misunderstood. The Play plugin is pull the appropriate reactivemongo-play-json according its version. When adding it as a separate dependency, you are forcing it, which can lead to a version conflict. It's recommanded to check against the latest version to confirm any issue. – cchantep Sep 07 '16 at 15:18
  • @cchantep Sorry, but I am now confused more than ever. You are saying that I don't need both libraries, if I just include `reactivemongo-play-json`? I have now changed `play2-reactivemongo` to 0.11.14 and now I am getting this slightly different error: `MongoError['The node set can not be reached! Please check your network connectivity (Supervisor-5/Connection-6)']`. BTW, I now have only one module in my Play project which includes both libraries. – John Doe Sep 07 '16 at 16:02
  • Please [read carefully](http://reactivemongo.org/releases/0.11/documentation/tutorial/play2.html). As indicated, if the dependency upon play2-reactivemongo is there, no separate dependency for reactivemongo-play-json. And as indicated, the latest version is 0.12-RC3, not 0.11.14. – cchantep Sep 07 '16 at 16:52
  • @cchantep Thank you for the explanation. But removing `reactivemongo-play-json` and upgrading to `0.12-RC3` didn't do the trick. I am now receiving this message: `MongoError['No primary node is available! (Supervisor-31/Connection-32)']`. – John Doe Sep 07 '16 at 21:11
  • You should make sure never to assign `driver`, `database` or `connection` from `ReactiveMongo` to application `val`s. Enabling logging for `play.modules.reactivemongo`, debug level should mention `Resolving database`. – cchantep Sep 07 '16 at 21:36
  • @cchantep So I should not use `lazy val collection: Future[JSONCollection] = reactiveMongoApi.database.map(_.collection[JSONCollection](collectionName))`? I enabled logging and received this log: `[reactivemongo-akka.actor.default-dispatcher-10] [akka://reactivemongo/user/Connection-4] Message [reactivemongo.core.actors.ChannelClosed] from Actor[akka://reactivemongo/deadLetters] to Actor[akka://reactivemongo/user/Connection-4#-383513682] was not delivered. [1] dead letters encountered.` – John Doe Sep 08 '16 at 15:11
  • Database and collection are lightweight references. Assigning the respective `Future` to val, even lazy, if it fails for the first time, it will never be recovered. That's a bad practice. – cchantep Sep 08 '16 at 16:35
  • @cchantep Thank you for the help. I replaced `lazy val` now with `def` as suggested in the documentation, but this error still occurs, even though the site does not reload immediately (as it used to before this changed), so I guess ReactiveMongo tries to recover the connection, but unfortunately without luck. This issue is really annoying. – John Doe Sep 09 '16 at 09:01
  • Unless you can share a focused reproducer, there is few chance you could get help from there. The [demo app](https://github.com/cchantep/reactivemongo-demo-app) has no issue with Play reload (e.g. after source changes) – cchantep Sep 09 '16 at 13:32
  • @JohnDoe did you ever find a resolution to this problem? – Serendipity Dec 06 '16 at 04:01

1 Answers1

0

I faced this issue as well; every time I reloaded my Play application (including hot reloads), I received hundreds of connection errors. After trying a couple times, my application would run fine until the next reload. This only started happening after I upgraded from ReactiveMongo 0.x to 1.x. I've tried running MongoDB (versions 3.2 through 4.0) locally, as both a native install and in a Docker container.

I "solved" it by adding the following connection options:

MongoConnectionOptions(maxIdleTimeMS = 100000, heartbeatFrequencyMS = 100)

The full connection looks like this:

private val driver = new reactivemongo.api.AsyncDriver
val connection: Future[MongoConnection] = driver.connect(List("localhost"), MongoConnectionOptions(maxIdleTimeMS = 100000, heartbeatFrequencyMS = 100))

I don't know why these values seem to work, or whether they're optimal. And I probably wouldn't recommend running a heartbeat of 100ms in production. However, it's working for my development needs, so I figured I'd share.

Greg
  • 733
  • 6
  • 14