Failing on AWS and Google Compute

[Srinivas Chavali]

Hello All,

   I am running into strange situation, I am using version 11.11 for play 2.5.1. My application is working fine with local mongodb. When I launch applicaiton on AWS or Google compute, it is stuck during collection.find, as a fact any type of operations on collection is stuck. I have installed mongodb on local instance itself, I am able to connect and add collection to mongodb through shell.

Can someone help me what might be going wrong

Configuration 

mongodb.uri = "mongodb://"${?MONGO_HOST}":"${?MONGO_PORT}"/service_collection"

mongo-async-driver {
  akka {
    loggers = ["akka.event.slf4j.Slf4jLogger"]
    loglevel = DEBUG
  }
}

Following are from my build and plugins file.

"org.reactivemongo" %% "play2-reactivemongo" % "0.11.11"

addSbtPlugin("com.typesafe.play" % "sbt-plugin" % "2.5.1")

[Cédric Chantepie]

Check the DEBUG/TRACE logs, without more information the issue can hardly be diagnosed.

[Srinivas Chavali]

Hello Cédric,

Apart from following logs I don't see any other logs related to reactivemongo, I have changed future composition to Await.result for 15 seconds, it is timing out for "collection.find". Do let me know if there is any other way I can get more logs related to reactivemongo

Reactive mongo logs

[info] application - ReactiveMongoApi starting...

[info] application - ReactiveMongoApi successfully configured with DB 'service_collection'! Servers:

[127.0.0.1:27017]

On mongodb side these are the following logs, I don't see any query reaching mongodb from logs. 

Mongodb logs

Sat Apr  9 01:20:25.891 [initandlisten] opening db:  local

Sat Apr  9 01:20:25.892 [initandlisten] enter repairDatabases (to check pdfile version #)

Sat Apr  9 01:20:25.892 [initandlisten] local

Sat Apr  9 01:20:25.892 [initandlisten] service_collection

Sat Apr  9 01:20:25.892 [initandlisten] opening db:  service_collection

Sat Apr  9 01:20:25.893 [initandlisten] done repairDatabases

Sat Apr  9 01:20:25.893 [initandlisten] run command local.$cmd { create: "startup_log", size: 10485760, capped: true }

Sat Apr  9 01:20:25.893 [initandlisten] opening db:  local

Sat Apr  9 01:20:25.893 [initandlisten] create collection local.startup_log { create: "startup_log", size: 10485760, capped: true }

Sat Apr  9 01:20:25.893 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:75 0ms

Sat Apr  9 01:20:25.893 [initandlisten] insert local.startup_log ninserted:1 keyUpdates:0  0ms

Sat Apr  9 01:20:25.893 [initandlisten] fd limit hard:64000 soft:64000 max conn: 51200

Sat Apr  9 01:20:25.893 [initandlisten] waiting for connections on port 27017

Sat Apr  9 01:20:25.893 BackgroundJob starting: TTLMonitor

Sat Apr  9 01:20:25.893 BackgroundJob starting: PeriodicTask::Runner

Sat Apr  9 01:20:25.893 BackgroundJob starting: ClientCursorMonitor

Sat Apr  9 01:20:25.893 [websvr] fd limit hard:64000 soft:64000 max conn: 51200

Sat Apr  9 01:20:25.894 [websvr] admin web console waiting for connections on port 28017

Sat Apr  9 01:20:25.894 BackgroundJob starting: snapshot

Sat Apr  9 01:20:33.471 [initandlisten] connection accepted from 127.0.0.1:58316 #1 (1 connection now open)

Sat Apr  9 01:20:33.473 [initandlisten] connection accepted from 127.0.0.1:58317 #2 (2 connections now open)

Sat Apr  9 01:20:33.473 [initandlisten] connection accepted from 127.0.0.1:58318 #3 (3 connections now open)

Sat Apr  9 01:20:33.475 [initandlisten] connection accepted from 127.0.0.1:58319 #4 (4 connections now open)

Sat Apr  9 01:20:33.475 [initandlisten] connection accepted from 127.0.0.1:58320 #5 (5 connections now open)

Sat Apr  9 01:20:33.475 [initandlisten] connection accepted from 127.0.0.1:58321 #6 (6 connections now open)

Sat Apr  9 01:20:33.477 [initandlisten] connection accepted from 127.0.0.1:58322 #7 (7 connections now open)

Sat Apr  9 01:20:33.477 [initandlisten] connection accepted from 127.0.0.1:58323 #8 (8 connections now open)

Sat Apr  9 01:20:33.477 [initandlisten] connection accepted from 127.0.0.1:58324 #9 (9 connections now open)

Sat Apr  9 01:20:33.477 [initandlisten] connection accepted from 127.0.0.1:58325 #10 (10 connections now open)

[Srinivas Chavali]

Hello,

   For me first operation was "find" which is stuck indefinitely may be because of connection issues. Later I changed my code first operation as insert, it reported following exception, I tried again, insert went through. It seems "find" operation is indefinitely waiting for connection establishment. 

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[ConnectionNotInitialized: MongoError['Connection is missing metadata (like protocol version, etc.) The connection pool is probably being initialized.']]]

at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:269)

at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:195)

at play.api.GlobalSettings$class.onError(GlobalSettings.scala:160)

at play.api.DefaultGlobal$.onError(GlobalSettings.scala:188)

at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:98)

at play.core.server.netty.PlayRequestHandler$$anonfun$2$$anonfun$apply$1.applyOrElse(PlayRequestHandler.scala:99)

at play.core.server.netty.PlayRequestHandler$$anonfun$2$$anonfun$apply$1.applyOrElse(PlayRequestHandler.scala:98)

at scala.concurrent.Future$$anonfun$recoverWith$1.apply(Future.scala:344)

at scala.concurrent.Future$$anonfun$recoverWith$1.apply(Future.scala:343)

at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)

Caused by: reactivemongo.core.errors.ConnectionNotInitialized: MongoError['Connection is missing metadata (like protocol version, etc.) The connection pool is probably being initialized.']

at reactivemongo.core.errors.ConnectionNotInitialized$.MissingMetadata(errors.scala:71)

at reactivemongo.api.collections.GenericCollection$class.insert(genericcollection.scala:364)

at reactivemongo.api.collections.bson.BSONCollection.insert(bsoncollection.scala:68)

at com.byg.repository.MongoCouponRepo.saveCoupon(CouponRepo.scala:85)

at com.byg.services.CouponServiceImpl$$anonfun$create$1.apply(CouponService.scala:80)

at com.byg.services.CouponServiceImpl$$anonfun$create$1.apply(CouponService.scala:63)

at controllers.CouponController$$anonfun$create$1.apply(CouponController.scala:69)

at controllers.CouponController$$anonfun$create$1.apply(CouponController.scala:54)

at play.api.mvc.Action$.invokeBlock(Action.scala:498)

at play.api.mvc.Action$.invokeBlock(Action.scala:495)

[Cédric Chantepie]

Check the way you are resolving the database. You should be using connection.database(dbName).

[Srinivas Chavali]

Thanks Cédric.

I am using reactivemongo-play here is my controller and repository objects. Following is the code(in short form). If this code has problem, I am wondering why is it working on local machine and digital ocean as well.

@Singleton

class ServiceController @Inject()(actorSystem: ActorSystem,

                                 reactiveMongoApi: ReactiveMongoApi,

                                 repo: CouponRepo) extends Controller with MongoController with ReactiveMongoComponents {

}

@Singleton

class MongoRepo @Inject()(reactiveMongoApi: ReactiveMongoApi) extends ServiceRepo {

  lazy val collection: BSONCollection = reactiveMongoApi.db("service_collection")

  def findById(id: String) = {

    collection.find(BSONDocument("id" -> id))

[Cédric Chantepie]

You didn't indicate the used version. If >= 0.11.10 you should use reactiveMongoApi.database instead of .db.

[Srinivas Chavali]

I am using 0.11.11

reactiveMongoApi.database is returning Future[DefaultDB] instead of BSONCollection

"org.reactivemongo" %% "play2-reactivemongo" % "0.11.11",

[Cédric Chantepie]

Yes, and that's intended to be coherent with the asynchronous nature if the driver.