not authorized on heroku_appXXX to execute command (mongolab)

[Francis De Brabandere]

Since https://github.com/ReactiveMongo/ReactiveMongo/issues/361 was closed I'm falling back to the mailinglist as requested

In short:

Used to have problems from time to time to connect to mongolab from heroku (mostly on startup)

Since mongolab updated to 3.0.6 I can not connect any more

App to reproduce showing reactivemongo not working and official reactive mongo driver working correctly:

import java.lang.Long

import com.mongodb.async.SingleResultCallback
import com.mongodb.async.client.MongoClients
import reactivemongo.api.MongoConnection.ParsedURI
import reactivemongo.api._
import reactivemongo.core.commands._
import reactivemongo.core.commands.Count

import scala.concurrent.Future
import scala.concurrent.ExecutionContext.Implicits.global

import play.api.libs.iteratee.Iteratee

import reactivemongo.bson.BSONDocument
import reactivemongo.api.collections.bson.BSONCollection

import scala.util.{Success, Failure}


object Test extends App{
  import reactivemongo.api._
  import scala.concurrent.ExecutionContext.Implicits.global

  val mongoUrl = "mongodb://heroku_app4877663_A:x...@ds033297.mongolab.com:33297/heroku_app4877663"

  val databaseName = "heroku_app4877663"
  val connectionName = "broadcasts"

  println("start reactivemongo")
  testReactiveMongo()
  println("start reactivejava")
  testReactiveJava()
  println("done")

  def testReactiveMongo() = {
    val driver = new MongoDriver
    val uri = MongoConnection
      .parseURI(mongoUrl)
      .get

    println(uri.db)
    println(uri.hosts)
    println(uri.options)
    println(uri.authenticate.get.db)
    println(uri.authenticate.get.user)
    println(uri.authenticate.get.password)

    val connection = driver.connection(uri)

    val db = connection(databaseName)

    val collection: Collection = db(connectionName)

    val futureCount = db.command(
      Count(collection.name)
    )
    futureCount.onComplete {
      case Success(count) => println("found " + count + " documents")
      case Failure(e) => e.printStackTrace()
    }


    Thread.sleep(10000)
    driver.close()
  }

  def testReactiveJava() = {
    // Use a Connection String
    val mongoClient = MongoClients.create(mongoUrl)

    val database = mongoClient.getDatabase(databaseName)

    val collection = database.getCollection(connectionName)

    collection.count(new SingleResultCallback[Long] {
      override def onResult(count: Long, t: Throwable): Unit = {
        if(count != null){
          println("found " + count + " documents")
        }
        if(t != null){
          t.printStackTrace()
        }
      }
    })

    Thread.sleep(10000)
    mongoClient.close()
  }
}

output:

mongotest start reactivemongo

mongotest Some(heroku_app4877663)

mongotest List((ds033297.mongolab.com,33297))

mongotest MongoConnectionOptions(0,None,false,false,CrAuthentication,false,false,10,GetLastError(WaitForAknowledgments(1),false,false,None),reactivemongo.api.ReadPreference$Primary$@fa36558)

mongotest heroku_app4877663

mongotest heroku_app4877663_A

mongotest xxx

mongotest 15:16:18.276 [reactivemongo-akka.actor.default-dispatcher-4] INFO  reactivemongo.core.actors.MongoDBSystem - The node set is now available

mongotest 15:16:18.277 [reactivemongo-akka.actor.default-dispatcher-4] INFO  reactivemongo.core.actors.MongoDBSystem - The primary is now available

mongotest[ERROR] reactivemongo.core.commands.DefaultCommandError: BSONCommandError['command count failed because the 'ok' field is missing or equals 0'] with original doc {

mongotest[ERROR]   ok: BSONDouble(0.0),

mongotest[ERROR]   errmsg: "not authorized on heroku_app4877663 to execute command { count: "broadcasts" }",

mongotest[ERROR]   code: BSONInteger(13)

mongotest[ERROR] }

mongotest[ERROR] at reactivemongo.core.commands.CommandError$.apply(commands.scala:149)

mongotest[ERROR] at reactivemongo.core.commands.CommandError$$anonfun$checkOk$default$3$1.apply(commands.scala:160)

mongotest[ERROR] at reactivemongo.core.commands.CommandError$$anonfun$checkOk$default$3$1.apply(commands.scala:160)

mongotest[ERROR] at reactivemongo.core.commands.CommandError$$anonfun$checkOk$3.apply(commands.scala:163)

mongotest[ERROR] at reactivemongo.core.commands.CommandError$$anonfun$checkOk$3.apply(commands.scala:161)

mongotest[ERROR] at scala.Option.flatMap(Option.scala:171)

mongotest[ERROR] at reactivemongo.core.commands.CommandError$.checkOk(commands.scala:161)

mongotest[ERROR] at reactivemongo.core.commands.Count$.apply(commands.scala:388)

mongotest[ERROR] at reactivemongo.core.commands.BSONCommandResultMaker$class.apply(commands.scala:91)

mongotest[ERROR] at reactivemongo.core.commands.Count$.apply(commands.scala:386)

mongotest[ERROR] at reactivemongo.api.DB$$anonfun$command$1.apply(database.scala:78)

mongotest[ERROR] at reactivemongo.api.DB$$anonfun$command$1.apply(database.scala:78)

mongotest[ERROR] at reactivemongo.utils.EitherMappableFuture$$anonfun$mapEither$1.apply(utils.scala:61)

mongotest[ERROR] at reactivemongo.utils.EitherMappableFuture$$anonfun$mapEither$1.apply(utils.scala:61)

mongotest[ERROR] at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:251)

mongotest[ERROR] at scala.concurrent.Future$$anonfun$flatMap$1.apply(Future.scala:249)

mongotest[ERROR] at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32)

mongotest[ERROR] at scala.concurrent.impl.ExecutionContextImpl$AdaptedForkJoinTask.exec(ExecutionContextImpl.scala:121)

mongotest[ERROR] at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)

mongotest[ERROR] at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.pollAndExecAll(ForkJoinPool.java:1253)

mongotest[ERROR] at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1346)

mongotest[ERROR] at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)

mongotest[ERROR] at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

mongotest 15:16:27.480 [reactivemongo-akka.actor.default-dispatcher-3] INFO  reactivemongo.core.actors.MongoDBSystem - Received Close message, going to close connections and moving on stage Closing

mongotest 15:16:27.499 [reactivemongo-akka.actor.default-dispatcher-3] INFO  reactivemongo.core.actors.MongoDBSystem - MongoDBSystem Actor[akka://reactivemongo/user/Connection-2#294187851] is stopping.

mongotest 15:16:27.501 [reactivemongo-akka.actor.default-dispatcher-3] WARN  reactivemongo.core.actors.MongoDBSystem - MongoDBSystem Actor[akka://reactivemongo/user/Connection-2#294187851] stopped.

mongotest [INFO] [10/01/2015 15:16:27.501] [reactivemongo-akka.actor.default-dispatcher-4] [akka://reactivemongo/deadLetters] Message [reactivemongo.core.actors.Closed$] from Actor[akka://reactivemongo/user/Monitor-3#1261349263] to Actor[akka://reactivemongo/deadLetters] was not delivered. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.

mongotest [INFO] [10/01/2015 15:16:27.506] [reactivemongo-akka.actor.default-dispatcher-5] [akka://reactivemongo/user/Supervisor-1] Message [akka.dispatch.sysmsg.Terminate] from Actor[akka://reactivemongo/user/Supervisor-1#951721970] to Actor[akka://reactivemongo/user/Supervisor-1#951721970] was not delivered. [2] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.

mongotest start reactivejava

mongotest[ERROR] Oct 01, 2015 3:16:27 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: Cluster created with settings {hosts=[ds033297.mongolab.com:33297], mode=SINGLE, requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', maxWaitQueueSize=500}

mongotest[ERROR] Oct 01, 2015 3:16:27 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: No server chosen by ReadPreferenceServerSelector{readPreference=primary} from cluster description ClusterDescription{type=UNKNOWN, connectionMode=SINGLE, all=[ServerDescription{address=ds033297.mongolab.com:33297, type=UNKNOWN, state=CONNECTING}]}. Waiting for 30000 ms before timing out

mongotest[ERROR] Oct 01, 2015 3:16:28 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: Opened connection [connectionId{localValue:1, serverValue:217752}] to ds033297.mongolab.com:33297

mongotest[ERROR] Oct 01, 2015 3:16:28 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: Monitor thread successfully connected to server with description ServerDescription{address=ds033297.mongolab.com:33297, type=REPLICA_SET_PRIMARY, state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 0, 6]}, minWireVersion=0, maxWireVersion=3, electionId=560c5b7f3b42fd6adabcd5ea, maxDocumentSize=16777216, roundTripTimeNanos=99194699, setName='rs-ds033297', canonicalAddress=ds033297-b.mongolab.com:33297, hosts=[ds033297-b.mongolab.com:33297], passives=[], arbiters=[], primary='ds033297-b.mongolab.com:33297', tagSet=TagSet{[]}}

mongotest[ERROR] Oct 01, 2015 3:16:29 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: Opened connection [connectionId{localValue:2, serverValue:217753}] to ds033297.mongolab.com:33297

mongotest found 1315 documents

mongotest[ERROR] Oct 01, 2015 3:16:37 PM com.mongodb.diagnostics.logging.JULLogger log

mongotest[ERROR] INFO: Closed connection [connectionId{localValue:2, serverValue:217753}] to ds033297.mongolab.com:33297 because the pool has been closed.

mongotest done

mongotest ... finished with exit code 0

Let me know if extra debug logging/testing is needed to debug this, or if I should again create an issue for this.

Cheers,
Francis

[Francis De Brabandere]

Seems this has nothing to do with the previous ticket, just mongodb 3.x authentication incompatibility. We are having the same issue for a system running outside of heroku.

F

[Cédric Chantepie]

ReactiveMongo 0.11 supports the SCRAM-SHA1 as authMode in the connection option, for MongoDB 3 in fresh install (not legacy mode). Best regards.

[Stephen Couchman]

Running 0.11.7 in play 2.4

I'm having the same problem now that MongoLab updated to 3.0, but the logs aren't very revealing as to what the nature of the problem is (in fact somewhat extra-confusing as they seem to say it worked and then fail).  I've successfully connected using the mongo CLI, so I know I have connectivity at least.  Is there any way to figure out why the connection is failing?

I set RM's logging level to Trace, they seem to say it authenticated, but obviously it didn't succeed.  The logs are from a local test run, but they match up with what I get from running on Heroku:

[info] - application - ReactiveMongoApi starting...
[warn] - reactivemongo.api.MongoDriver - No mongo-async-driver configuration found
[info] - application - ReactiveMongoApi successfully started with DB 'heroku_4sfp2b40'! Servers:
                [ds035533.mongolab.com:35533]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x3dcdcd8c]
[debug] - reactivemongo.core.actors.MongoDBSystem - received a request expecting a response
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) connected
[debug] - reactivemongo.core.actors.MongoDBSystem - NO CHANNEL, error with promise scala.concurrent.impl.Promise$DefaultPromise@3705875f
[debug] - reactivemongo.api.Failover2 - 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.11-0.11.7.jar:0.11.7]
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$pickChannel$4.apply(actors.scala:635) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$pickChannel$4.apply(actors.scala:635) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at scala.Option.getOrElse(Option.scala:121) ~[scala-library-2.11.7.jar:na]
        at reactivemongo.core.actors.MongoDBSystem$class.pickChannel(actors.scala:635) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at reactivemongo.core.actors.LegacyDBSystem.pickChannel(actors.scala:750) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$4.applyOrElse(actors.scala:304) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170) ~[scala-library-2.11.7.jar:na]
        at akka.actor.Actor$class.aroundReceive(Actor.scala:467) ~[akka-actor_2.11.jar:na]
        at reactivemongo.core.actors.LegacyDBSystem.aroundReceive(actors.scala:750) ~[reactivemongo_2.11-0.11.7.jar:0.11.7]
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516) ~[akka-actor_2.11.jar:na]
        at akka.actor.ActorCell.invoke(ActorCell.scala:487) ~[akka-actor_2.11.jar:na]
        at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238) ~[akka-actor_2.11.jar:na]
        at akka.dispatch.Mailbox.run(Mailbox.scala:220) ~[akka-actor_2.11.jar:na]
        at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397) [akka-actor_2.11.jar:na]
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.7.jar:na]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #1036897676 connected. NodeSet status: {{NodeSet None Node[ds035533.mongolab.com:35533: Unknown (1/1 available connections), latency=0], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329317,0,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0xd2d51aa5]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x2f367f3b]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x8295fecb]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0xa7e53f62]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x2ce02455]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x1ee16303]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0xafd573b4]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x66e4b78b]
[trace] - reactivemongo.core.nodeset.ChannelFactory - created a new channel: [id: 0x6679f6fb]
[info] - reactivemongo.core.actors.MongoDBSystem - The node set is now available
[info] - reactivemongo.core.actors.MongoDBSystem - The primary is now available
[debug] - reactivemongo.core.actors.MonitorActor - set: a node is available: ProtocolMetadata(reactivemongo.core.protocol.MongoWireVersion$V24AndBefore$@267d0da6,reactivemongo.core.protocol.MongoWireVersion$V30$@4290c71,16777216,48000000,1000)
[debug] - reactivemongo.core.actors.MonitorActor - set: a primary is available
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #-757785947 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (2/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #-2104099125 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (3/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) connected
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #792100667 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (4/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(81,1329319,1000,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) connected
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #-1478148254 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (5/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #518087427 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (6/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #752886869 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (7/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #1719269115 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (8/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #1726265227 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (9/10 available connections), latency=69], auth=Set() }}
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 1036897676: 45d700f8593a54c2
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.actors.MongoDBSystem - Channel #-1344965708 connected. NodeSet status: {{NodeSet None Node[ds035533-a.mongolab.com:35533: Primary (10/10 available connections), latency=69], auth=Set() }}
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329320,1,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329321,2,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329328,3,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) messageReceived Response(MessageHeader(81,1329327,1001,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(-757785947)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329329,4,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) messageReceived Response(MessageHeader(81,1329333,1002,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(792100667)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329330,5,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329331,6,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) messageReceived Response(MessageHeader(81,1329337,1003,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(-2104099125)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel -757785947: d38ab326a3081417
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) messageReceived Response(MessageHeader(81,1329338,1006,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(518087427)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) messageReceived Response(MessageHeader(81,1329339,1004,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(-1478148254)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) messageReceived Response(MessageHeader(81,1329340,1005,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(752886869)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329332,7,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) messageReceived Response(MessageHeader(81,1329341,1009,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(1719269115)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) messageReceived Response(MessageHeader(81,1329342,1008,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(1726265227)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) messageReceived Response(MessageHeader(81,1329343,1007,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(-1344965708)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329334,8,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(87,1329335,2000,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(401,1329336,9,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=401, cap=401),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 792100667: 58ed6c05ed228c7e
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel -2104099125: e11643dc16e141a9
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel -1478148254: 8f0a52c63f7b77e8
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 518087427: 919d9d5938bbdbad
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 752886869: 921c011e38db20e5
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 1719269115: 44c863e8b9421dc7
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 1726265227: 4ef20fd855cf3d14
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel -1344965708: 5448c50edcfae83c
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 1036897676
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-757785947) messageReceived Response(MessageHeader(87,1329344,2001,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(-757785947)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=792100667) messageReceived Response(MessageHeader(87,1329345,2002,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(792100667)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! -757785947
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 792100667
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=518087427) messageReceived Response(MessageHeader(87,1329346,2005,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(518087427)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 518087427
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=752886869) messageReceived Response(MessageHeader(87,1329347,2006,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(752886869)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 752886869
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1478148254) messageReceived Response(MessageHeader(87,1329348,2004,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(-1478148254)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! -1478148254
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1719269115) messageReceived Response(MessageHeader(87,1329349,2007,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(1719269115)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 1719269115
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(81,1329350,1010,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=81, cap=81),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-2104099125) messageReceived Response(MessageHeader(87,1329351,2003,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(-2104099125)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got nonce for channel 1036897676: debcd39d73c1a502
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=-1344965708) messageReceived Response(MessageHeader(87,1329352,2009,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(-1344965708)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1726265227) messageReceived Response(MessageHeader(87,1329353,2008,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(1726265227)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! -2104099125
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! -1344965708
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 1726265227
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(87,1329354,2010,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=87, cap=87),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - AUTH: got authenticated response! 1036897676
[debug] - reactivemongo.core.actors.MongoDBSystem - received a request expecting a response
[debug] - reactivemongo.core.actors.MongoDBSystem - Sending request expecting response Request(3001,0,Query(0,heroku_4sfp2b40.$cmd,0,1),BufferSequence(DynamicChannelBuffer(ridx=0, widx=42, cap=64),WrappedArray()),reactivemongo.api.ReadPreference$Primary$@51a41fb5,None) by connection Connection([id: 0x3dcdcd8c, /74.76.17.12:36152 => ds035533.mongolab.com/54.144.40.175:35533],Connected,Set(),None) of node ds035533-a.mongolab.com:35533
[trace] - reactivemongo.core.actors.MongoDBSystem - registering awaiting response for requestID 3001, awaitingResponses: Map(3001 -> AwaitingResponse(3001,1036897676,scala.concurrent.impl.Promise$DefaultPromise@2866a82d,false,false))
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is requested!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) a write is complete!
[trace] - reactivemongo.core.protocol.MongoHandler - (channel=1036897676) messageReceived Response(MessageHeader(165,1329366,3001,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=165, cap=165),ResponseInfo(1036897676)) will be send to Actor[akka://reactivemongo/user/Connection-2#1985426663]
[debug] - reactivemongo.core.actors.MongoDBSystem - Got a response from 1036897676! Will give back message=Response(MessageHeader(165,1329366,3001,1),Reply(8,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=165, cap=165),ResponseInfo(1036897676)) to promise scala.concurrent.impl.Promise$DefaultPromise@2866a82d
[trace] - reactivemongo.core.actors.MongoDBSystem - {3001} [MongoDB26 Write Op response] sending a success!
[trace] - reactivemongo.api.Failover2 - Got an non retryable error, completing with a failure...
reactivemongo.api.commands.bson.DefaultBSONCommandError: CommandError[code=13, errmsg=not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }, doc: {
  ok: BSONDouble(0.0),
  errmsg: "not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }",
  code: BSONInteger(13)
}]
[error] - application -


! @6nk0hk48l - Internal server error, for (GET) [/monitor/list] ->


play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[DefaultBSONCommandError: CommandError[code=13, errmsg=not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }, doc: {
  ok: BSONDouble(0.0),
  errmsg: "not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }",
  code: BSONInteger(13)
}]]]
        at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.2.jar:2.4.2]
        at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.2.jar:2.4.2]
        at play.api.GlobalSettings$class.onError(GlobalSettings.scala:179) [play_2.11-2.4.2.jar:2.4.2]
        at play.api.DefaultGlobal$.onError(GlobalSettings.scala:212) [play_2.11-2.4.2.jar:2.4.2]
        at play.api.http.GlobalSettingsHttpErrorHandler.onServerError(HttpErrorHandler.scala:94) [play_2.11-2.4.2.jar:2.4.2]
        at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:158) [play-netty-server_2.11-2.4.2.jar:2.4.2]
        at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:155) [play-netty-server_2.11-2.4.2.jar:2.4.2]
        at scala.runtime.AbstractPartialFunction.apply(AbstractPartialFunction.scala:36) [scala-library-2.11.7.jar:na]
        at scala.util.Failure$$anonfun$recover$1.apply(Try.scala:216) [scala-library-2.11.7.jar:na]
        at scala.util.Try$.apply(Try.scala:192) [scala-library-2.11.7.jar:na]
        at scala.util.Failure.recover(Try.scala:216) [scala-library-2.11.7.jar:na]
        at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
        at scala.concurrent.Future$$anonfun$recover$1.apply(Future.scala:324) [scala-library-2.11.7.jar:na]
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.7.jar:na]
        at play.api.libs.iteratee.Execution$trampoline$.executeScheduled(Execution.scala:109) [play-iteratees_2.11-2.4.2.jar:2.4.2]
        at play.api.libs.iteratee.Execution$trampoline$.execute(Execution.scala:71) [play-iteratees_2.11-2.4.2.jar:2.4.2]
        at scala.concurrent.impl.CallbackRunnable.executeWithValue(Promise.scala:40) [scala-library-2.11.7.jar:na]
        at scala.concurrent.impl.Promise$DefaultPromise.tryComplete(Promise.scala:248) [scala-library-2.11.7.jar:na]
        at scala.concurrent.Promise$class.complete(Promise.scala:55) [scala-library-2.11.7.jar:na]
        at scala.concurrent.impl.Promise$DefaultPromise.complete(Promise.scala:153) [scala-library-2.11.7.jar:na]
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235) [scala-library-2.11.7.jar:na]
        at scala.concurrent.Future$$anonfun$map$1.apply(Future.scala:235) [scala-library-2.11.7.jar:na]
        at scala.concurrent.impl.CallbackRunnable.run(Promise.scala:32) [scala-library-2.11.7.jar:na]
        at akka.dispatch.BatchingExecutor$AbstractBatch.processBatch(BatchingExecutor.scala:55) [akka-actor_2.11.jar:na]
        at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply$mcV$sp(BatchingExecutor.scala:91) [akka-actor_2.11.jar:na]
        at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91) [akka-actor_2.11.jar:na]
        at akka.dispatch.BatchingExecutor$BlockableBatch$$anonfun$run$1.apply(BatchingExecutor.scala:91) [akka-actor_2.11.jar:na]
        at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:72) [scala-library-2.11.7.jar:na]
        at akka.dispatch.BatchingExecutor$BlockableBatch.run(BatchingExecutor.scala:90) [akka-actor_2.11.jar:na]
        at akka.dispatch.TaskInvocation.run(AbstractDispatcher.scala:40) [akka-actor_2.11.jar:na]
        at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397) [akka-actor_2.11.jar:na]
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [scala-library-2.11.7.jar:na]
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [scala-library-2.11.7.jar:na]
Caused by: reactivemongo.api.commands.bson.DefaultBSONCommandError: CommandError[code=13, errmsg=not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }, doc: {
  ok: BSONDouble(0.0),
  errmsg: "not authorized on heroku_4sfp2b40 to execute command { count: "logs", limit: 0, skip: 0 }",
  code: BSONInteger(13)
}]

Thanks,

Stephen

[Olivier Droz]

Hi Francis and Cedric, 

I'm having the same issue since the migration of mongolab from 2.6 to 3.0.

I updated my reactivemongo driver to 0.11 (I'm using Play 2.3.9)

I tried to force SHA in Global .scala as such:

import reactivemongo.api.MongoConnectionOptions

import reactivemongo.api.ScramSha1Authentication

object Global extends play.api.GlobalSettings {

   def driver: reactivemongo.api.MongoDriver = new reactivemongo.api.MongoDriver

  val conOpts = MongoConnectionOptions(authMode = ScramSha1Authentication)

  play.api.Logger.debug("Connection Options: " + conOpts.toString())

  val connection = driver.connection(List("localhost:27017", "dsxxxx.mongolab.com:xxx"), options = conOpts)
...}

But i'm still unable to connect from my herokuapp. (Not sure it's the right way to do though...)

Cedric, what do you mean by MongoDB 3 in fresh install (not legacy mode)? What doe it mean heroku wise?

Thanks a lot for your inputs ;-)

On Thursday, October 1, 2015 at 3:32:51 PM UTC+2, Francis De Brabandere wrote:

[Julien L.]

I used to have the same problem, authentication issue when executing query on MongoLab.

I solved this problem by adding ?authMode=scram-sha1 to the mongodb.uri.

[Stephen Couchman]

Wow, yep that did it like magic.

Thanks!

[Cédric Chantepie]

Hi, btw both programatically setting the ScramSha1AuthMode in connection options or from the URI ?authMode=scram-sha1 must work (the later being parsed to do the first).

We will try to update the demo app deployed on Heroku and using MongoLab, as a live example of the current state of the auth.

Best regards

[Olivier Droz]

Hi Cédric, all

Thanks a lot for the info. 

Setting Parma in the URI worked like a charm on my side as well

--
You received this message because you are subscribed to a topic in the Google Groups "ReactiveMongo - http://reactivemongo.org" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/reactivemongo/x3OZ6-hIIXk/unsubscribe.
To unsubscribe from this group and all its topics, send an email to reactivemong...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--
Olivier Droz

[Francis De Brabandere]

Thanks. Was indeed able to fix this issue using the following application.conf entry:

mongodb.uri=${?MONGOLAB_URI}"?authMode=scram-sha1"

But deciding on the auth mode should be the job of the driver (like the mongodb driver correctly handles)...

Cheers,

F

[Cédric Chantepie]

Until the MongoDB protocol allows to determine which is the mode to be used with MongoDB3 (which is not the case as far as I see), it needs to be explicitly choosen.

[Cédric Chantepie]

The demo app using MongoLab on Heroku has been updated: https://reactivemongo-demo-app.herokuapp.com/

[James Roper]

Surely at some point before authentication, it's possible to determine the MongoDB version?  Since the default authentication mechanism for MongoDB 3 is scram-sha1, this should be the default used by the client when it detects that it's connecting to MongoDB 3.  Perhaps in the configuration, we need a new option called "UseDefault", which will use the default for the version of MongoDB being connected to.

[Cédric Chantepie]

Hi, The default auth mode is not SCRAM SHA1 for MongoDB3, but for fresh install of MongoDB3. All DB migrated from previous versions are in legacy mode, with no auth change. The protocol version is not sufficient to determine the authMode. Best regards.

[Francis De Brabandere]

The mongodb java driver is switching by server version:

https://github.com/mongodb/mongo-java-driver/blob/master/driver-core/src/main/com/mongodb/connection/DefaultAuthenticator.java#L41

Could it be that this legacy mode supports both Native and ScramSha1 but a fresh install will only support ScramSha1?

Cheers,

Francis

On 13 October 2015 at 09:02, Cédric Chantepie <chantep...@gmail.com> wrote:

Hi, The default auth mode is not SCRAM SHA1 for MongoDB3, but for fresh install of MongoDB3. All DB migrated from previous versions are in legacy mode, with no auth change. The protocol version is not sufficient to determine the authMode. Best regards.

[Cédric Chantepie]

On Tuesday, 13 October 2015 09:20:31 UTC+2, Francis De Brabandere wrote:

The mongodb java driver is switching by server version:

https://github.com/mongodb/mongo-java-driver/blob/master/driver-core/src/main/com/mongodb/connection/DefaultAuthenticator.java#L41

Could it be that this legacy mode supports both Native and ScramSha1 but a fresh install will only support ScramSha1?

Nope. Legacy means it's still in MONGOCR. Once the MongoDB is moved to SCRAM-SHA1, the change is irreversible (either on fresh install or by explicit choice on migrated DB).

[Matt Fellows]

Thanks Cedric, where is the updated code for this? Assuming it was originally here at https://github.com/sgodbillon/reactivemongo-demo-app, it doesn't appear to have changed for months.

Pulling that repo down, updating the URI with the authMode=scram-sha1 results in the same errors we are seeing here.

I've been trying for several hours now but am unable to get a working example.

[Cédric Chantepie]

The code hasn't been updated (still by the same repo), only the MongoDB URI for MongoLab (with authMode).

[Joe San]

Is there any GitHub source for this that I could have a look at?

[Francis De Brabandere]

Well, the not being able to connect at all issue is fixed with the auth flag

https://github.com/francisdb/belgiantv/commit/908b1b51317ff16c99898bff702087f0504caa07

But now I again have the 'DatabaseException['not authorized for query on heroku_app4877663.broadcasts' ] on every wake up of my heroku hobby dino. Previously this was sporadicly the case.

Subsequent requests work properly.

F

[Francis De Brabandere]

Just got the error 3 min ago:

reactivemongo.core.errors.DetailedDatabaseException: DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)]
        at reactivemongo.core.errors.ReactiveMongoException$.apply(errors.scala:32)
        at reactivemongo.core.protocol.Response.error$lzycompute(protocol.scala:271)
        at reactivemongo.core.protocol.Response.error(protocol.scala:266)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$6.applyOrElse(actors.scala:483)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171)
        at akka.actor.Actor$class.aroundReceive(Actor.scala:467)
        at reactivemongo.core.actors.StandardDBSystem.aroundReceive(actors.scala:757)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516)
        at akka.actor.ActorCell.invoke(ActorCell.scala:487)
        at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238)
        at akka.dispatch.Mailbox.run(Mailbox.scala:220)
        at akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)

But as you can see the site works properly after this initial issue

http://belgiantv.herokuapp.com/

F

[Cédric Chantepie]

There is some undergoing refactoring, to have failover during startup, in case of network latency or of unexpected load.

[Francis De Brabandere]

Great, let me know if you need a tester :-)

On 23 October 2015 at 00:39, Cédric Chantepie <chantep...@gmail.com> wrote:

There is some undergoing refactoring, to have failover during startup, in case of network latency or of unexpected load.

[Cédric Chantepie]

Thanks, you can try MongoConnection.database (instead of MongoConnection.db or MongoConnection.apply) with a the 0.12.0-SNAPSHOT.
This should at least wait for nodeset to be available (should be improve to wait for the primary, according the current readpref/write concern).

Best regards.

[Francis De Brabandere]

Can I get to this MongoConnection.database when using play plugin/ReactiveMongoApi?

--

[Cédric Chantepie]

When using the indicated snapshot, with the ReactiveMongoApi instance, you can do .connection.database instead of .db .

[Francis De Brabandere]

Something has changed but not fixed. At least now I consistently have the error on the first connection:

private lazy val db = reactiveMongoApi.connection.database("heroku_appXXX")
private lazy val movieCollection: Future[JSONCollection] = db.map(_.collection[JSONCollection]("movies"))
movieCollection.flatMap(_.find(...)...)

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[DetailedDatabaseException: DatabaseException['not authorized for query on heroku_appXXX.movies' (code = 13)]]]

at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.3.jar:2.4.3]

at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.3.jar:2.4.3]

at global.ErrorReportingHttpErrorHandler.onServerError(ErrorReportingHttpErrorHandler.scala:30) [classes/:na]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:158) [play-netty-server_2.11-2.4.3.jar:2.4.3]

at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:155) [play-netty-server_2.11-2.4.3.jar:2.4.3]

Caused by: reactivemongo.core.errors.DetailedDatabaseException: DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)]

at reactivemongo.core.errors.ReactiveMongoException$.apply(errors.scala:32) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]

at reactivemongo.core.protocol.Response.error$lzycompute(protocol.scala:271) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]

at reactivemongo.core.protocol.Response.error(protocol.scala:266) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]

at reactivemongo.core.actors.MongoDBSystem$$anonfun$6.applyOrElse(actors.scala:512) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]

at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171) ~[scala-library-2.11.7.jar:na]

Cheers,
Francis

On 7 November 2015 at 16:57, Cédric Chantepie <chantep...@gmail.com> wrote:

When using the indicated snapshot, with the ReactiveMongoApi instance, you can do .connection.database instead of .db .

--

[Cédric Chantepie]

Have you tried to pass a FailoverStrategy to the .database function, to adjust according Heroku/MongoLab latency?

[Francis De Brabandere]

Seems to me that this is not working as expected. I ask for 20 retries but it drops out with the error at the 6th try. As always after this initial error everything works fine.

private lazy val db = reactiveMongoApi.connection("heroku_app4877663", FailoverStrategy(50.milliseconds, 20, {n => val w = n * 2; println(w); w}))

Output:

[info]    play.api.Play      - Application started (Dev)
2
4
6
8
10
12
[error]   application        -

! @6oc3g1i84 - Internal server error, for (GET) [/] ->

play.api.http.HttpErrorHandlerExceptions$$anon$1: Execution exception[[DetailedDatabaseException: DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)]]]
	at play.api.http.HttpErrorHandlerExceptions$.throwableToUsefulException(HttpErrorHandler.scala:265) ~[play_2.11-2.4.3.jar:2.4.3]
	at play.api.http.DefaultHttpErrorHandler.onServerError(HttpErrorHandler.scala:191) ~[play_2.11-2.4.3.jar:2.4.3]
	at global.ErrorReportingHttpErrorHandler.onServerError(ErrorReportingHttpErrorHandler.scala:30) [classes/:na]
	at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:158) [play-netty-server_2.11-2.4.3.jar:2.4.3]
	at play.core.server.netty.PlayDefaultUpstreamHandler$$anonfun$9$$anonfun$apply$1.applyOrElse(PlayDefaultUpstreamHandler.scala:155) [play-netty-server_2.11-2.4.3.jar:2.4.3]
Caused by: reactivemongo.core.errors.DetailedDatabaseException: DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)]
	at reactivemongo.core.errors.ReactiveMongoException$.apply(errors.scala:32) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]
	at reactivemongo.core.protocol.Response.error$lzycompute(protocol.scala:269) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]
	at reactivemongo.core.protocol.Response.error(protocol.scala:264) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]
	at reactivemongo.core.actors.MongoDBSystem$$anonfun$6.applyOrElse(actors.scala:483) ~[reactivemongo_2.11-0.12.0-SNAPSHOT.jar:0.12.0-SNAPSHOT]
	at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:171) ~[scala-library-2.11.7.jar:na]

On 6 December 2015 at 15:35, Cédric Chantepie <chantep...@gmail.com> wrote:

Have you tried to pass a FailoverStrategy to the .database function, to adjust according Heroku/MongoLab latency?

--

[Francis De Brabandere]

And to be clear, this is not when running on heroku but locally and directly connecting to mongolab.com

Cheers,

F

[Cédric Chantepie]

You can try the newly published snapshot

[Joseph Hui]

Encountered similar problem with the following code, i.e., not authorized on first load and no error on subsequent load, and tried with 0.12.0-SNAPSHOT, which has no error when run with a "activator clean" every time. Same error if run without  "activator clean". 

package controllers

import play.api._

import play.api.mvc._

import javax.inject.Inject

import play.api.mvc.Controller

import scala.util.{Success, Failure}

import scala.concurrent.{ ExecutionContext, Future }

import scala.concurrent.duration._

import scala.concurrent.ExecutionContext.Implicits.global

import play.api.Play.current

import play.api.libs.json._

import reactivemongo.bson.BSONDocument

import reactivemongo.api.commands.WriteResult

import reactivemongo.api.Cursor

import play.modules.reactivemongo._

import play.modules.reactivemongo.json._

import play.modules.reactivemongo.json.collection.JSONCollection

import play.modules.reactivemongo.ReactiveMongoApi

class Application @Inject() (val reactiveMongoApi: ReactiveMongoApi)

  extends Controller with MongoController with ReactiveMongoComponents {

  def collection: JSONCollection = db.collection[JSONCollection]("user-credentials")

  

  def index = Action.async {

    val cursor: Cursor[JsObject] = collection.

      // find all people with name `name`

      find(Json.obj()).

      // sort them by creation date

      sort(Json.obj("created" -> -1)).

      // perform the query and get a cursor of JsObject

      cursor[JsObject]

    // gather all the JsObjects in a list

    val futurePersonsList: Future[List[JsObject]] = cursor.collect[List]()

    // transform the list into a JsArray

    val futurePersonsJsonArray: Future[JsArray] =

      futurePersonsList.map { persons => Json.arr(persons) }

    // everything's ok! Let's reply with the array

    futurePersonsJsonArray.map { persons =>

      // Ok(views.html.index("Your new application is ready." + persons))

      Ok(persons)

    }

    // Future { Ok("OK") }

[Cédric Chantepie]

Hi,

Same suggestion, try using .database instead of .db .

Best regards

[Joseph Hui]

Confirm .database fix the problem.

[Francis De Brabandere]

Strange, that did not fix it for me as shown in the example in my last post. Am I doing it the wrong way?

[Joseph Hui]

I got my collection like the following:

protected def collection  = for {

  db <- reactiveMongoApi.database

  collection <- Future { db.collection[JSONCollection]("XXXXX") } 

} yield collection

def find()(implicit ec: ExecutionContext): Future[List[JsObject]] = 

  collection.flatMap(_.find(Json.obj()).cursor[JsObject].collect[List]())

The differences between yours and mine are "lazy" and reactiveMongoApi.database vs reactiveMongoApi.connection.database 

Would they be the problems?

[Cédric Chantepie]

Hi Francis, the new function has been updated since your last message (07/12/2015) in the 0.11.8 and 0.11.9 releases. Best regards.

[Francis De Brabandere]

My last message was on 12/12/2015 but now I see it never actually arrived at the list, strange

I still have the issue with 0.11.9 and 0.12.0 snapshot

Connecting directly to mongolab, no heroku, no play framework

My code for testing:

      val config = ConfigFactory.load()

      val driver = new MongoDriver()

      val uri = MongoConnection.parseURI(config.getString("mongodb.uri")).get

      val connection = driver.connection(uri)

      val dbFuture = connection.database(uri.db.get, FailoverStrategy(100.milliseconds, 20, {n => val w = n * 2; println(w); w}))

      val q = dbFuture.flatMap { db =>

        val broadcastCollection = db[BSONCollection]("broadcasts")

        broadcastCollection

          .find(BSONDocument())

          .cursor[Broadcast]()

          .collect[List](1)

      }

      val result = Await.result(q, 20.seconds)

      result.foreach(println)

      connection.close()

      driver.close()

This test fails half of the time, see log below

The failover strategy seems not to work correctly as it does not reach the requested number of retries:

=============== failing ==========================

2

4

22:17:33.032 [reactivemongo-akka.actor.default-dispatcher-3] INFO  r.core.actors.MongoDBSystem - The node set is now available

22:17:33.032 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MonitorActor - set: a node is available: ProtocolMetadata(reactivemongo.core.protocol.MongoWireVersion$V24AndBefore$@7d649155,reactivemongo.core.protocol.MongoWireVersion$V30$@6f930f75,16777216,48000000,1000)

22:17:33.034 [reactivemongo-akka.actor.default-dispatcher-3] INFO  r.core.actors.MongoDBSystem - The primary is now available

22:17:33.034 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MonitorActor - set: a primary is available

22:17:33.136 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 2038871821: ScramSha1Challenge(1)

6

22:17:33.325 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - received a request expecting a response

22:17:33.327 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - Sending request expecting response Request(3000,0,Query(0,heroku_app4877663.broadcasts,0,0),BufferSequence(DynamicChannelBuffer(ridx=0, widx=5, cap=32),WrappedArray()),reactivemongo.api.ReadPreference$Primary$@6397a3b3,None) by connection Connection([id: 0x7986b70d, /192.168.0.218:61384 => ds033297.mongolab.com/54.162.185.166:33297],Connected,Set(),Some(ScramSha1Authenticating(heroku_app4877663,heroku_app4877663_A,XXX,&ye8l<9:\$p0%!uo2wvA`zMU,n,,n=heroku_app4877663_A,r=&ye8l<9:\$p0%!uo2wvA`zMU,Some(1),Some([B@60b7971f),1))) of node ds033297-b.mongolab.com:33297

22:17:33.419 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 2038871821

22:17:33.423 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.531 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - Got a response from 2038871821! Will give back message=Response(MessageHeader(118,78212547,3000,1),Reply(2,0,0,1),LittleEndianHeapChannelBuffer(ridx=36, widx=118, cap=118),ResponseInfo(2038871821)) to promise scala.concurrent.impl.Promise$DefaultPromise@6221b6ca

22:17:33.533 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - {3000} sending a failure... (reactivemongo.core.errors.DetailedDatabaseException: DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)])

22:17:33.615 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 2038871821

22:17:33.630 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel -616948034: ScramSha1Challenge(1)

[info] ReactiveMongoTest

22:17:33.644 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 871016662: ScramSha1Challenge(1)

22:17:33.674 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 495938284: ScramSha1Challenge(1)

22:17:33.690 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 1088659692: ScramSha1Challenge(1)

22:17:33.704 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 1014356604: ScramSha1Challenge(1)

[info]

22:17:33.724 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 1823348625: ScramSha1Challenge(1)

22:17:33.738 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel -1144216263: ScramSha1Challenge(1)

[info] reactivemongo should

22:17:33.764 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel -1777109884: ScramSha1Challenge(1)

[error]   ! connect to mongolab

22:17:33.783 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got challenge for channel 1996272226: ScramSha1Challenge(1)

[error]    DatabaseException['not authorized for query on heroku_app4877663.broadcasts' (code = 13)] (errors.scala:32)

22:17:33.811 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! -616948034

22:17:33.811 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.812 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 871016662

22:17:33.812 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.813 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 495938284

22:17:33.813 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

[error] reactivemongo.core.errors.ReactiveMongoException$.apply(errors.scala:32)

[error] reactivemongo.core.protocol.Response.error$lzycompute(protocol.scala:269)

[error] reactivemongo.core.protocol.Response.error(protocol.scala:264)

22:17:33.814 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1088659692

[error] reactivemongo.core.actors.MongoDBSystem$$anonfun$6.applyOrElse(actors.scala:512)

22:17:33.814 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

[error] akka.actor.Actor$class.aroundReceive(Actor.scala:467)

[error] reactivemongo.core.actors.StandardDBSystem.aroundReceive(actors.scala:792)

[error] akka.actor.ActorCell.receiveMessage(ActorCell.scala:516)

[error] akka.actor.ActorCell.invoke(ActorCell.scala:487)

[error] akka.dispatch.Mailbox.processMailbox(Mailbox.scala:238)

[error] akka.dispatch.Mailbox.run(Mailbox.scala:220)

[error] akka.dispatch.ForkJoinExecutorConfigurator$AkkaForkJoinTask.exec(AbstractDispatcher.scala:397)

[info]

22:17:33.827 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1014356604

22:17:33.827 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.841 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1823348625

22:17:33.842 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.873 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! -1144216263

22:17:33.874 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.892 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! -1777109884

22:17:33.892 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

[info]

[info] Total for specification ReactiveMongoTest

[info] Finished in 1 second, 347 ms

[info] 1 example, 0 failure, 1 error

[info]

22:17:33.915 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 871016662

22:17:33.920 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! -616948034

22:17:33.921 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 495938284

22:17:33.923 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1088659692

22:17:33.923 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1996272226

22:17:33.923 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - 2-phase SCRAM-SHA1 negociation

22:17:33.938 [reactivemongo-akka.actor.default-dispatcher-2] DEBUG r.core.actors.MongoDBSystem - AUTH: got authenticated response! 1014356604

[Cédric Chantepie]

Hi, you can give a try to 0.11.10 .

[Francis De Brabandere]

Hi Cédric,

Good news, I can no longer reproduce the issue :-)

I even have the impression that things are better now even without the Future[DefaultDB]

Thanks,

F

On 23 February 2016 at 10:37, Cédric Chantepie <chantep...@gmail.com> wrote:

Hi, you can give a try to 0.11.10 .

[Cédric Chantepie]

Good news, thanks for the feedback.

[Olivier Droz]

Francis, Are you using 0.11.10?

Thanks

Olivier Droz

Ing. Inf. Dipl. EPF

Rte de la Feuillère 29

1010 Lausanne

www.olivierdroz.ch

On Thu, Feb 25, 2016 at 12:27 AM, Cédric Chantepie <chantep...@gmail.com> wrote:

Good news, thanks for the feedback.

[Francis De Brabandere]

yes, but I am less sure that it is fixed, I do however am sure I have the issue way less often, I guess it's a matter of setting a different FailoverStrategy

[Cédric Chantepie]

Now the failover is used accross the different cases. Then it has to be coherent with the network latency.

[Cédric Chantepie]

For information, now the test environment of the driver is running one plan with high network latency and appropriate fail over, to validate such case. Best regards

[Francis De Brabandere]

I'm currently seeing an other error when my heroku instance wakes up:

java.util.concurrent.TimeoutException: Futures timed out after [3000 milliseconds]
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219)
        at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:153)
        at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169)
        at scala.concurrent.Await$$anonfun$ready$1.apply(package.scala:169)
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:169)
        at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java:3640)
        at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:167)
        at scala.concurrent.Await$.ready(package.scala:169)
        at reactivemongo.api.DefaultCursor$Impl$$anonfun$awaitFailover$1.apply(cursor.scala:474)
        at reactivemongo.api.DefaultCursor$Impl$$anonfun$awaitFailover$1.apply(cursor.scala:474)
        at scala.concurrent.impl.Future$PromiseCompletingRunnable.liftedTree1$1(Future.scala:24)
        at scala.concurrent.impl.Future$PromiseCompletingRunnable.run(Future.scala:24)

On 7 March 2016 at 17:52, Cédric Chantepie <chantep...@gmail.com> wrote:

For information, now the test environment of the driver is running one plan with high network latency and appropriate fail over, to validate such case. Best regards

[Cédric Chantepie]

Are you using aggregate?

[Francis De Brabandere]

Nope. see

https://github.com/francisdb/belgiantv/blob/master/app/models/BroadcastRepository.scala

https://github.com/francisdb/belgiantv/blob/master/app/models/MovieRepository.scala

On 8 March 2016 at 13:20, Cédric Chantepie <chantep...@gmail.com> wrote:

Are you using aggregate?

[Cédric Chantepie]

In these code, the .database call using FailoverStrategy is comment out? What's happening with?

[Francis De Brabandere]

It's not needed as I don't have this 'not authorized on heroku_appXXX to execute command' any more even without it.

But will switch back to that if you think it is related.

On Mar 9, 2016 00:04, "Cédric Chantepie" <chantep...@gmail.com> wrote:

In these code, the .database call using FailoverStrategy is comment out? What's happening with?

--

[Cédric Chantepie]

Without the failover at database resolution, the default one is used, considering latency at Heroku ... Moreover, the `.db` will probably be deprecated.

[Francis De Brabandere]

I can confirm that this is fixed when using the .database call using FailoverStrategy. Thanks!

On 9 March 2016 at 09:19, Cédric Chantepie <chantep...@gmail.com> wrote:

Without the failover at database resolution, the default one is used, considering latency at Heroku ... Moreover, the `.db` will probably be deprecated.

[Cédric Chantepie]

Since 0.11.11, the default failover can be defined in the connection URI, using the rm.failover option: http://reactivemongo.org/releases/0.12/documentation/tutorial/connect-database.html