Login/Register
Strange MongoError (with ReactiveMongo) when Play reloads application
Asked Answered
mongodbscalaplayframeworkreactivemongoplay-reactivemongo
A

1

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! :-)

Aura answered 6/9, 2016 at 17:46 Comment(17)
Please indicate the used versions, and possibly test with latest versions is not already – Verdun
@Verdun Hi! I added all versions. – Aura
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) – Verdun
Latest version is 0.12-RC3 – Verdun
@JohnDoe I get the same exception while running tests (restarting applications). – Crankpin
That error No primary node sounds like it is dealing with a replicaset. Is that how your mongodb is configured? Or is it a single database server? – Unbalance
No, I actually run MongoDB locally just for developing purposes. Everything is in default configuration. @Verdun 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? – Aura
@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. – Verdun
@Verdun 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. – Aura
Please read carefully. 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. – Verdun
@Verdun 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)']. – Aura
You should make sure never to assign driver, database or connection from ReactiveMongo to application vals. Enabling logging for play.modules.reactivemongo, debug level should mention Resolving database. – Verdun
@Verdun 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. – Aura
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. – Verdun
@Verdun 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. – Aura
Unless you can share a focused reproducer, there is few chance you could get help from there. The demo app has no issue with Play reload (e.g. after source changes) – Verdun
@JohnDoe did you ever find a resolution to this problem? – Camel
D
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.

Deadening answered 11/2, 2023 at 23:23 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.