Unexpected connection behavior with maxIdleTimeMS

[mikeb]

Hello,

I found unexpected connection behavior when maxIdleTimeMS set to value bigger than 0. It's closing connection even when it shouldn't.
I'm using Scala 2.13, ReactiveMongo 1.0.10.

I have following example code used with local MongoDB:

val driver = AsyncDriver()
val options = MongoConnectionOptions(
keepAlive = true,
sslEnabled = false,
maxIdleTimeMS = 8000,
appName = None,
readConcern = ReadConcern.Majority
)

val conn = driver.connect(Seq("localhost:27017"), options)
val db: DB = Await.result(conn.flatMap(_.database("test")), 20.seconds)
val coll : BSONCollection = db.collection("users")

val document = BSONDocument( //document in DB
"firstName" -> "Stephane",
"lastName" -> "Godbillon",
"age" -> 29
)

try {
while (true) {
Thread.sleep(7000)
val query = coll.find(BSONDocument("age" -> 29)).one
logger.info("Result: " + Await.result(query, 20.seconds).map(_ => "OK"))
}
} finally {
driver.close()
}

Expected behavior for me would be just printing: " [INFO] Result: Some(OK)"
Idle is set to 8 seconds, and every 7 seconds there is request, there should not be any idle timeout.

What happens is:
2022-01-23 16:20:32,686 ReactiveMongoDriverTest$ - [INFO] Result: Some(OK)
2022-01-23 16:20:33,591 reactivemongo.core.actors.MongoDBSystem - [WARN] [Supervisor-1/Connection-1] The entire node set is unreachable, is there a network problem?
2022-01-23 16:20:46,798 reactivemongo.api.Failover - [ERROR] [Supervisor-1/Connection-1] Got an error, no more attempts to do. Completing with a failure...
reactivemongo.core.actors.Exceptions$ChannelNotFoundException: MongoError['No active channel can be found to the primary node: 'localhost:27017' { connected:0, channels:11 } (Supervisor-1/Connection-1)']

Additional findings:

With maxIdleTimeMS = 12000, it works correctly (for most of time).
But connection is closed and open to MongoDB constantly, every few seconds (seems like number of seconds between reconnect matches maxIdleTimeMS). I can see it in MongoDB server logs:

mongo            | 2022-01-23T15:36:40.749+0000 I NETWORK  [listener] connection accepted from 172.27.0.1:34328 #305 (11 connections now open)
mongo            | 2022-01-23T15:36:40.749+0000 I NETWORK  [listener] connection accepted from 172.27.0.1:34330 #306 (12 connections now open)
mongo            | 2022-01-23T15:36:40.750+0000 I NETWORK  [listener] connection accepted from 172.27.0.1:34334 #307 (13 connections now open)
mongo            | 2022-01-23T15:36:40.751+0000 I NETWORK  [listener] connection accepted from 172.27.0.1:34336 #308 (14 connections now open)
mongo            | 2022-01-23T15:36:52.760+0000 I NETWORK  [conn301] end connection 172.27.0.1:34320 (13 connections now open)
mongo            | 2022-01-23T15:36:52.760+0000 I NETWORK  [conn308] end connection 172.27.0.1:34336 (12 connections now open)
mongo            | 2022-01-23T15:36:52.761+0000 I NETWORK  [conn305] end connection 172.27.0.1:34328 (11 connections now open)
....


With maxIdleTimeMS = 0, it works as it should:
- driver is not reopening connections
- no errors in application

Is this some bug or configuration problem? 

Thanks,

Michal

[Cédric Chantepie]

If you try something like `mongodb://localhost:27017/test?maxIdleTimeMS=8000`

10:31:52.536 ReactiveMongo INFO  [r.a.Driver] :: No mongo-async-driver configuration found
reactivemongo.api.MongoConnection$URIParsingException: Invalid URI options: maxIdleTimeMS(8000) < heartbeatFrequencyMS(10000)

[mikeb]

That's true, with connection string I see validation.

Yet, even with connection sting and higher maxIdleTimeMS, like 12seconds, connection is still closed and opened over and over again. 

[Cédric Chantepie]

Cannot reproduce with a clean code.

[Cédric Chantepie]

Neither with :

import scala.concurrent._
import scala.concurrent.duration._

import reactivemongo.api._
import reactivemongo.api.bson.BSONDocument
import reactivemongo.api.bson.collection._

object Test {
  import ExecutionContext.Implicits._

  def foo(): Unit = {

    val driver = AsyncDriver()
    val options = MongoConnectionOptions(
      keepAlive = true,
      sslEnabled = false,
      maxIdleTimeMS = 8000,
      appName = None,
      readConcern = ReadConcern.Majority)

    val conn = driver.connect(Seq("localhost:27017"), options)
    val db: DB = Await.result(conn.flatMap(_.database("test")), 20.seconds)
    val coll: BSONCollection = db.collection("users")

    /* Never used

    val document = BSONDocument( //document in DB
      "firstName" -> "Stephane",
      "lastName" -> "Godbillon",
      "age" -> 29)

     */

    try {
      while (true) {
        Thread.sleep(7000)

        val query = coll.find(BSONDocument("age" -> 29)).one

        val res = Await.result(query, 20.seconds).map(_ => "OK")

        println(s"Result: ${res}")
      }
    } finally {
      driver.close()

      ()
    }
  }
}