com.mongodb.MongoException: not talking to master and retries used up

JIRA | Mike Conigliaro | 6 years ago
  1. 0

    Something (I don't know what yet) caused one of my shards to fail over. When I look at the logs on the old master, I see this: Thu May 12 15:47:22 [conn21060] remove example.userEventsJournal query: { _id: ObjectId('4d56ea01fa00a03b38c17fde') } 232ms Thu May 12 15:47:23 [conn21060] remove example.userEventsJournal query: { _id: ObjectId('4d56ea0a04e235872bd9e29e') } 291ms Thu May 12 15:47:25 [conn20802] query example.$cmd ntoreturn:1 command: { distinct: "cookbook", key: "cookbookId", query: {} } reslen:1445 1401ms Thu May 12 15:47:25 [conn20841] query example.$cmd ntoreturn:1 command: { distinct: "cookbook", key: "cookbookId", query: {} } reslen:1445 664ms Thu May 12 15:47:28 [dur] lsn set 120976684 Thu May 12 15:47:41 [conn21062] getmore local.oplog.rs cid:3926093491549750074 getMore: { ts: { $gte: new Date(5605849438531616885) } } bytes:789 nreturned:3 12119ms Thu May 12 15:47:41 [ReplSetHealthPollTask] replSet member mongodb05.example.com:27018 PRIMARY Thu May 12 15:47:41 [conn21035] Assertion: 13312:replSet error : logOp() but not primary? 0x55f1b9 0x712a31 0x7108f2 0x668fa1 0x66ba60 0x75814f 0x75aae1 0x8a75ee 0x8ba510 0x7fb642df69ca 0x7fb6423a570d /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x129) [0x55f1b9] /usr/bin/mongod() [0x712a31] /usr/bin/mongod(_ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_Pb+0x42) [0x7108f2] /usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0x1131) [0x668fa1] /usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66ba60] /usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75814f] /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x75aae1] /usr/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a75ee] /usr/bin/mongod(thread_proxy+0x80) [0x8ba510] /lib/libpthread.so.0(+0x69ca) [0x7fb642df69ca] /lib/libc.so.6(clone+0x6d) [0x7fb6423a570d] Thu May 12 15:47:41 [conn21035] update example.stats query: { entityId: "hal_livingSocial_DFA03", bucketId: "groups", variationId: "_default" } exception 13312 replSet error : logOp() but not primary? 1ms Thu May 12 15:47:41 [conn20999] Assertion: 13312:replSet error : logOp() but not primary? 0x55f1b9 0x712a31 0x7108f2 0x668fa1 0x66ba60 0x75814f 0x75aae1 0x8a75ee 0x8ba510 0x7fb642df69ca 0x7fb6423a570d /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x129) [0x55f1b9] /usr/bin/mongod() [0x712a31] /usr/bin/mongod(_ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_Pb+0x42) [0x7108f2] /usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0x1131) [0x668fa1] /usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66ba60] /usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75814f] /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x75aae1] /usr/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a75ee] /usr/bin/mongod(thread_proxy+0x80) [0x8ba510] /lib/libpthread.so.0(+0x69ca) [0x7fb642df69ca] /lib/libc.so.6(clone+0x6d) [0x7fb6423a570d] There are many more of those "logOp() but not primary?" messages after this. Followed by several messages like this: Thu May 12 15:47:41 [conn21003] update example.stats query: { entityId: "hal_livingSocial_DFA03", bucketId: "groups", variationId: "_default" } exception 13312 replSet error : logOp() but not primary? 1ms Thu May 12 15:47:41 [conn21033] assertion 13435 not master and slaveok=false ns:example.ads query:{ adId: "hal_livingSocial_cookbook_dfa_winning02" } Thu May 12 15:47:41 [conn21033] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21024] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation07" } Thu May 12 15:47:41 [conn21024] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21012] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn21012] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21018] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation07" } Thu May 12 15:47:41 [conn21018] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn20992] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn20992] ntoskip:0 ntoreturn:-1Thu May 12 15:47:41 [conn20994] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn20994] ntoskip:0 ntoreturn:-1 Then this: Thu May 12 15:47:43 [replica set sync] replSet our last op time written: May 12 15:47:29:10 Thu May 12 15:47:43 [replica set sync] replset source's GTE: May 12 15:47:41:1 Thu May 12 15:47:43 [replica set sync] replSet rollback 0 Thu May 12 15:47:43 [replica set sync] replSet rollback 1 Thu May 12 15:47:43 [replica set sync] replSet rollback 2 FindCommonPoint Thu May 12 15:47:43 [replica set sync] replSet info rollback our last optime: May 12 15:47:29:10 Thu May 12 15:47:43 [replica set sync] replSet info rollback their last optime: May 12 15:47:42:a Thu May 12 15:47:43 [replica set sync] replSet info rollback diff in end of log times: -13 secondsThu May 12 15:47:43 [replica set sync] replSet rollback found matching events at May 12 15:47:29:d Thu May 12 15:47:43 [replica set sync] replSet rollback findcommonpoint scanned : 38 Thu May 12 15:47:43 [replica set sync] replSet replSet rollback 3 fixup Thu May 12 15:47:43 [replica set sync] replSet rollback 3.5 Thu May 12 15:47:43 [replica set sync] replSet rollback 4 n:3 Thu May 12 15:47:43 [replica set sync] replSet minvalid=May 12 15:47:42 4dcc011e:a Thu May 12 15:47:43 [replica set sync] replSet rollback 4.6 Thu May 12 15:47:43 [replica set sync] replSet rollback 4.7 Thu May 12 15:47:43 [replica set sync] replSet rollback 5 d:0 u:3 Thu May 12 15:47:43 [replica set sync] replSet rollback 6 Thu May 12 15:47:43 [replica set sync] replSet rollback 7 Thu May 12 15:47:43 [replica set sync] replSet rollback done Thu May 12 15:47:43 [dur] lsn set 120982480 And finally: Thu May 12 15:48:24 [dur] lsn set 121000882 Thu May 12 15:48:25 [ReplSetHealthPollTask] DBClientCursor::init call() failed Thu May 12 15:48:25 [ReplSetHealthPollTask] replSet info mongodb05.example.com:27018 is down (or slow to respond): DBClientBase::findOne: transport error: mongodb05.example.com:27018 query: { replSetHeartbeat: "2", v: 7, pv: 1, checkEmpty: false, from: "mongodb04.example.com:27018" } Thu May 12 15:48:25 [rs Manager] replSet info electSelf 0 Thu May 12 15:48:25 [rs Manager] replSet couldn't elect self, only received -9999 votes Thu May 12 15:48:29 [ReplSetHealthPollTask] replSet info mongodb05.example.com:27018 is up Thu May 12 15:49:10 [conn21155] query local.$cmd ntoreturn:1 command: { collstats: "oplog.rs" } reslen:284 3638ms Thu May 12 15:49:33 [dur] lsn set 121030916 Thu May 12 15:50:20 [dur] lsn set 121060941 On the *new* master, I see this: Thu May 12 15:47:40 [ReplSetHealthPollTask] DBClientCursor::init call() failed Thu May 12 15:47:40 [ReplSetHealthPollTask] replSet info mongodb04.socialmedia.com:27018 is down (or slow to respond): DBClientBase::findOne: transport error: mongodb04.socialmedia.com:27018 query: { replSetHeartbeat: "2", v: 7, pv: 1, checkEmpty: false, from: "mongodb05.socialmedia.com:27018" } Thu May 12 15:47:40 [rs Manager] replSet info electSelf 1 Thu May 12 15:47:40 [rs Manager] replSet PRIMARY Thu May 12 15:47:41 [replica set sync] replSet stopping syncTail we are now primary Thu May 12 15:47:42 [ReplSetHealthPollTask] replSet info mongodb04.socialmedia.com:27018 is up Thu May 12 15:47:42 [ReplSetHealthPollTask] replSet member mongodb04.socialmedia.com:27018 RECOVERING Thu May 12 15:47:46 [conn52890] remove socialmedia.userEventsJournal query: { _id: ObjectId('4d56eb456655aa982210b2b9') } 115ms Thu May 12 15:47:46 [ReplSetHealthPollTask] replSet member mongodb04.socialmedia.com:27018 SECONDARY So failover appears to have completed successfully. Though now I'm seeing exceptions like this in my app: ERR [20110512-15:47:43.401] blueeyes: com.mongodb.MongoException: not talking to master and retries used up ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:227) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:295) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._check(DBCursor.java:354) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._hasNext(DBCursor.java:484) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor.hasNext(DBCursor.java:509) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.RealDatabaseCollection$$anon$1.hasNext(RealMongoImplementation.scala:82) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.IterableLike$class.isEmpty(IterableLike.scala:92) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.isEmpty(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.TraversableLike$class.headOption(TraversableLike.scala:483) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.headOption(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$SelectOneQueryBehaviour$class.query(QueryBehaviours.scala:128) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$MongoQueryBehaviour$class.apply(QueryBehaviours.scala:16) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:43) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14$$anonfun$submit$1.apply(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:50) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ReadWriteLock$class.writeLock(ReadWriteLock.scala:10) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anon$1.writeLock(Future.scala:22) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future.deliver(Future.scala:45) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14.submit(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker$$anonfun$run$1.apply$mcV$sp(Actor.scala:195) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$ActorContext$.withActorFn(Actor.scala:230) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker.run(Actor.scala:189) ERR [20110512-15:47:43.401] blueeyes: (...more...) I do not see any errors on the mongos.log around this time: Thu May 12 15:47:16 [Balancer] skipping balancing round because balancing is disabled Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb04.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb04.example.com:27018", "mongodb05.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4 Thu May 12 15:47:33 [LockPinger] dist_lock pinged successfully for: appserver01:1305178845:1804289383 Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb04.example.com:27018 { setName: "2", ismaster: false, secondary: true, hosts: [ "mongodb04.example.com:27018", "mongodb05.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], primary: "mongodb05.example.com:27018", maxBsonObjectSize: 16777216, ok: 1.0 } _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4 Thu May 12 15:47:46 BackgroundJob starting: ConnectBG Thu May 12 15:47:46 [Balancer] skipping balancing round because balancing is disabled Thu May 12 15:47:47 BackgroundJob starting: ConnectBG Thu May 12 15:47:50 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:48:03 [LockPinger] dist_lock pinged successfully for: appserver01:1305178845:1804289383 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4

    JIRA | 6 years ago | Michael Conigliaro
    com.mongodb.MongoException: not talking to master and retries used up
  2. 0

    After replica set failover in my sharded cluster, my app throws exceptions like this: ERR [20110512-15:47:43.401] blueeyes: com.mongodb.MongoException: not talking to master and retries used up ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:227) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:295) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._check(DBCursor.java:354) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._hasNext(DBCursor.java:484) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor.hasNext(DBCursor.java:509) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.RealDatabaseCollection$$anon$1.hasNext(RealMongoImplementation.scala:82) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.IterableLike$class.isEmpty(IterableLike.scala:92) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.isEmpty(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.TraversableLike$class.headOption(TraversableLike.scala:483) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.headOption(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$SelectOneQueryBehaviour$class.query(QueryBehaviours.scala:128) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$MongoQueryBehaviour$class.apply(QueryBehaviours.scala:16) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:43) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14$$anonfun$submit$1.apply(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:50) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ReadWriteLock$class.writeLock(ReadWriteLock.scala:10) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anon$1.writeLock(Future.scala:22) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future.deliver(Future.scala:45) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14.submit(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker$$anonfun$run$1.apply$mcV$sp(Actor.scala:195) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$ActorContext$.withActorFn(Actor.scala:230) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker.run(Actor.scala:189) ERR [20110512-15:47:43.401] blueeyes: (...more...) This may be related to https://jira.mongodb.org/browse/SERVER-3087

    JIRA | 6 years ago | Michael Conigliaro
    com.mongodb.MongoException: not talking to master and retries used up
  3. 0

    Something (I don't know what yet) caused one of my shards to fail over. When I look at the logs on the old master, I see this: Thu May 12 15:47:22 [conn21060] remove example.userEventsJournal query: { _id: ObjectId('4d56ea01fa00a03b38c17fde') } 232ms Thu May 12 15:47:23 [conn21060] remove example.userEventsJournal query: { _id: ObjectId('4d56ea0a04e235872bd9e29e') } 291ms Thu May 12 15:47:25 [conn20802] query example.$cmd ntoreturn:1 command: { distinct: "cookbook", key: "cookbookId", query: {} } reslen:1445 1401ms Thu May 12 15:47:25 [conn20841] query example.$cmd ntoreturn:1 command: { distinct: "cookbook", key: "cookbookId", query: {} } reslen:1445 664ms Thu May 12 15:47:28 [dur] lsn set 120976684 Thu May 12 15:47:41 [conn21062] getmore local.oplog.rs cid:3926093491549750074 getMore: { ts: { $gte: new Date(5605849438531616885) } } bytes:789 nreturned:3 12119ms Thu May 12 15:47:41 [ReplSetHealthPollTask] replSet member mongodb05.example.com:27018 PRIMARY Thu May 12 15:47:41 [conn21035] Assertion: 13312:replSet error : logOp() but not primary? 0x55f1b9 0x712a31 0x7108f2 0x668fa1 0x66ba60 0x75814f 0x75aae1 0x8a75ee 0x8ba510 0x7fb642df69ca 0x7fb6423a570d /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x129) [0x55f1b9] /usr/bin/mongod() [0x712a31] /usr/bin/mongod(_ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_Pb+0x42) [0x7108f2] /usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0x1131) [0x668fa1] /usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66ba60] /usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75814f] /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x75aae1] /usr/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a75ee] /usr/bin/mongod(thread_proxy+0x80) [0x8ba510] /lib/libpthread.so.0(+0x69ca) [0x7fb642df69ca] /lib/libc.so.6(clone+0x6d) [0x7fb6423a570d] Thu May 12 15:47:41 [conn21035] update example.stats query: { entityId: "hal_livingSocial_DFA03", bucketId: "groups", variationId: "_default" } exception 13312 replSet error : logOp() but not primary? 1ms Thu May 12 15:47:41 [conn20999] Assertion: 13312:replSet error : logOp() but not primary? 0x55f1b9 0x712a31 0x7108f2 0x668fa1 0x66ba60 0x75814f 0x75aae1 0x8a75ee 0x8ba510 0x7fb642df69ca 0x7fb6423a570d /usr/bin/mongod(_ZN5mongo11msgassertedEiPKc+0x129) [0x55f1b9] /usr/bin/mongod() [0x712a31] /usr/bin/mongod(_ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_Pb+0x42) [0x7108f2] /usr/bin/mongod(_ZN5mongo14_updateObjectsEbPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugEPNS_11RemoveSaverE+0x1131) [0x668fa1] /usr/bin/mongod(_ZN5mongo13updateObjectsEPKcRKNS_7BSONObjES2_bbbRNS_7OpDebugE+0x130) [0x66ba60] /usr/bin/mongod(_ZN5mongo14receivedUpdateERNS_7MessageERNS_5CurOpE+0x47f) [0x75814f] /usr/bin/mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_8SockAddrE+0x1941) [0x75aae1] /usr/bin/mongod(_ZN5mongo10connThreadEPNS_13MessagingPortE+0x21e) [0x8a75ee] /usr/bin/mongod(thread_proxy+0x80) [0x8ba510] /lib/libpthread.so.0(+0x69ca) [0x7fb642df69ca] /lib/libc.so.6(clone+0x6d) [0x7fb6423a570d] There are many more of those "logOp() but not primary?" messages after this. Followed by several messages like this: Thu May 12 15:47:41 [conn21003] update example.stats query: { entityId: "hal_livingSocial_DFA03", bucketId: "groups", variationId: "_default" } exception 13312 replSet error : logOp() but not primary? 1ms Thu May 12 15:47:41 [conn21033] assertion 13435 not master and slaveok=false ns:example.ads query:{ adId: "hal_livingSocial_cookbook_dfa_winning02" } Thu May 12 15:47:41 [conn21033] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21024] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation07" } Thu May 12 15:47:41 [conn21024] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21012] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn21012] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn21018] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation07" } Thu May 12 15:47:41 [conn21018] ntoskip:0 ntoreturn:-1 Thu May 12 15:47:41 [conn20992] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn20992] ntoskip:0 ntoreturn:-1Thu May 12 15:47:41 [conn20994] assertion 13435 not master and slaveok=false ns:example.cookbook query:{ cookbookId: "livingSocialBaselineVariation08" } Thu May 12 15:47:41 [conn20994] ntoskip:0 ntoreturn:-1 Then this: Thu May 12 15:47:43 [replica set sync] replSet our last op time written: May 12 15:47:29:10 Thu May 12 15:47:43 [replica set sync] replset source's GTE: May 12 15:47:41:1 Thu May 12 15:47:43 [replica set sync] replSet rollback 0 Thu May 12 15:47:43 [replica set sync] replSet rollback 1 Thu May 12 15:47:43 [replica set sync] replSet rollback 2 FindCommonPoint Thu May 12 15:47:43 [replica set sync] replSet info rollback our last optime: May 12 15:47:29:10 Thu May 12 15:47:43 [replica set sync] replSet info rollback their last optime: May 12 15:47:42:a Thu May 12 15:47:43 [replica set sync] replSet info rollback diff in end of log times: -13 secondsThu May 12 15:47:43 [replica set sync] replSet rollback found matching events at May 12 15:47:29:d Thu May 12 15:47:43 [replica set sync] replSet rollback findcommonpoint scanned : 38 Thu May 12 15:47:43 [replica set sync] replSet replSet rollback 3 fixup Thu May 12 15:47:43 [replica set sync] replSet rollback 3.5 Thu May 12 15:47:43 [replica set sync] replSet rollback 4 n:3 Thu May 12 15:47:43 [replica set sync] replSet minvalid=May 12 15:47:42 4dcc011e:a Thu May 12 15:47:43 [replica set sync] replSet rollback 4.6 Thu May 12 15:47:43 [replica set sync] replSet rollback 4.7 Thu May 12 15:47:43 [replica set sync] replSet rollback 5 d:0 u:3 Thu May 12 15:47:43 [replica set sync] replSet rollback 6 Thu May 12 15:47:43 [replica set sync] replSet rollback 7 Thu May 12 15:47:43 [replica set sync] replSet rollback done Thu May 12 15:47:43 [dur] lsn set 120982480 And finally: Thu May 12 15:48:24 [dur] lsn set 121000882 Thu May 12 15:48:25 [ReplSetHealthPollTask] DBClientCursor::init call() failed Thu May 12 15:48:25 [ReplSetHealthPollTask] replSet info mongodb05.example.com:27018 is down (or slow to respond): DBClientBase::findOne: transport error: mongodb05.example.com:27018 query: { replSetHeartbeat: "2", v: 7, pv: 1, checkEmpty: false, from: "mongodb04.example.com:27018" } Thu May 12 15:48:25 [rs Manager] replSet info electSelf 0 Thu May 12 15:48:25 [rs Manager] replSet couldn't elect self, only received -9999 votes Thu May 12 15:48:29 [ReplSetHealthPollTask] replSet info mongodb05.example.com:27018 is up Thu May 12 15:49:10 [conn21155] query local.$cmd ntoreturn:1 command: { collstats: "oplog.rs" } reslen:284 3638ms Thu May 12 15:49:33 [dur] lsn set 121030916 Thu May 12 15:50:20 [dur] lsn set 121060941 On the *new* master, I see this: Thu May 12 15:47:40 [ReplSetHealthPollTask] DBClientCursor::init call() failed Thu May 12 15:47:40 [ReplSetHealthPollTask] replSet info mongodb04.socialmedia.com:27018 is down (or slow to respond): DBClientBase::findOne: transport error: mongodb04.socialmedia.com:27018 query: { replSetHeartbeat: "2", v: 7, pv: 1, checkEmpty: false, from: "mongodb05.socialmedia.com:27018" } Thu May 12 15:47:40 [rs Manager] replSet info electSelf 1 Thu May 12 15:47:40 [rs Manager] replSet PRIMARY Thu May 12 15:47:41 [replica set sync] replSet stopping syncTail we are now primary Thu May 12 15:47:42 [ReplSetHealthPollTask] replSet info mongodb04.socialmedia.com:27018 is up Thu May 12 15:47:42 [ReplSetHealthPollTask] replSet member mongodb04.socialmedia.com:27018 RECOVERING Thu May 12 15:47:46 [conn52890] remove socialmedia.userEventsJournal query: { _id: ObjectId('4d56eb456655aa982210b2b9') } 115ms Thu May 12 15:47:46 [ReplSetHealthPollTask] replSet member mongodb04.socialmedia.com:27018 SECONDARY So failover appears to have completed successfully. Though now I'm seeing exceptions like this in my app: ERR [20110512-15:47:43.401] blueeyes: com.mongodb.MongoException: not talking to master and retries used up ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:227) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:295) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._check(DBCursor.java:354) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._hasNext(DBCursor.java:484) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor.hasNext(DBCursor.java:509) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.RealDatabaseCollection$$anon$1.hasNext(RealMongoImplementation.scala:82) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.IterableLike$class.isEmpty(IterableLike.scala:92) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.isEmpty(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.TraversableLike$class.headOption(TraversableLike.scala:483) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.headOption(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$SelectOneQueryBehaviour$class.query(QueryBehaviours.scala:128) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$MongoQueryBehaviour$class.apply(QueryBehaviours.scala:16) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:43) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14$$anonfun$submit$1.apply(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:50) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ReadWriteLock$class.writeLock(ReadWriteLock.scala:10) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anon$1.writeLock(Future.scala:22) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future.deliver(Future.scala:45) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14.submit(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker$$anonfun$run$1.apply$mcV$sp(Actor.scala:195) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$ActorContext$.withActorFn(Actor.scala:230) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker.run(Actor.scala:189) ERR [20110512-15:47:43.401] blueeyes: (...more...) I do not see any errors on the mongos.log around this time: Thu May 12 15:47:16 [Balancer] skipping balancing round because balancing is disabled Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb04.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb04.example.com:27018", "mongodb05.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:47:26 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4 Thu May 12 15:47:33 [LockPinger] dist_lock pinged successfully for: appserver01:1305178845:1804289383 Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:36 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb04.example.com:27018 { setName: "2", ismaster: false, secondary: true, hosts: [ "mongodb04.example.com:27018", "mongodb05.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], primary: "mongodb05.example.com:27018", maxBsonObjectSize: 16777216, ok: 1.0 } _check : 2/mongodb05.example.com:27018,mongodb04.example.com:27018,mongodb04.example.com:27018 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:47:46 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4 Thu May 12 15:47:46 BackgroundJob starting: ConnectBG Thu May 12 15:47:46 [Balancer] skipping balancing round because balancing is disabled Thu May 12 15:47:47 BackgroundJob starting: ConnectBG Thu May 12 15:47:50 [WriteBackListener] writebacklisten result: { noop: true, ok: 1.0 } Thu May 12 15:48:03 [LockPinger] dist_lock pinged successfully for: appserver01:1305178845:1804289383 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb10.example.com:27018 { setName: "4", ismaster: true, secondary: false, hosts: [ "mongodb10.example.com:27018", "mongodb11.example.com:27018" ], arbiters: [ "mongodb12.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 1 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb01.example.com:27018 { setName: "1", ismaster: true, secondary: false, hosts: [ "mongodb01.example.com:27018", "mongodb02.example.com:27018" ], arbiters: [ "mongodb03.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 2 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb05.example.com:27018 { setName: "2", ismaster: true, secondary: false, hosts: [ "mongodb05.example.com:27018", "mongodb04.example.com:27018" ], arbiters: [ "mongodb06.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 3 Thu May 12 15:48:06 [ReplicaSetMonitorWatcher] ReplicaSetMonitor::_checkConnection: mongodb07.example.com:27018 { setName: "3", ismaster: true, secondary: false, hosts: [ "mongodb07.example.com:27018", "mongodb08.example.com:27018" ], arbiters: [ "mongodb09.example.com:27018" ], maxBsonObjectSize: 16777216, ok: 1.0 } checking replica set: 4

    JIRA | 6 years ago | Mike Conigliaro
    com.mongodb.MongoException: not talking to master and retries used up
  4. Speed up your debug routine!

    Automated exception search integrated into your IDE

  5. 0

    After replica set failover in my sharded cluster, my app throws exceptions like this: ERR [20110512-15:47:43.401] blueeyes: com.mongodb.MongoException: not talking to master and retries used up ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:227) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:295) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._check(DBCursor.java:354) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor._hasNext(DBCursor.java:484) ERR [20110512-15:47:43.401] blueeyes: at com.mongodb.DBCursor.hasNext(DBCursor.java:509) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.RealDatabaseCollection$$anon$1.hasNext(RealMongoImplementation.scala:82) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.IterableLike$class.isEmpty(IterableLike.scala:92) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.isEmpty(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at scala.collection.TraversableLike$class.headOption(TraversableLike.scala:483) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.IterableViewImpl.headOption(RealMongoImplementation.scala:122) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$SelectOneQueryBehaviour$class.query(QueryBehaviours.scala:128) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.QueryBehaviours$MongoQueryBehaviour$class.apply(QueryBehaviours.scala:16) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:43) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14$$anonfun$submit$1.apply(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:50) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:46) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ReadWriteLock$class.writeLock(ReadWriteLock.scala:10) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future$$anon$1.writeLock(Future.scala:22) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.Future.deliver(Future.scala:45) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14.submit(Actor.scala:17) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker$$anonfun$run$1.apply$mcV$sp(Actor.scala:195) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$ActorContext$.withActorFn(Actor.scala:230) ERR [20110512-15:47:43.401] blueeyes: at blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker.run(Actor.scala:189) ERR [20110512-15:47:43.401] blueeyes: (...more...) This may be related to https://jira.mongodb.org/browse/SERVER-3087

    JIRA | 6 years ago | Mike Conigliaro
    com.mongodb.MongoException: not talking to master and retries used up
  6. 0

    Response Not Received When There's a MongoException

    GitHub | 3 years ago | erturne
    com.mongodb.MongoException: not talking to master and retries used up

  1. sriharshakiran 2 times, last 7 months ago
5 unregistered visitors
Not finding the right solution?
Take a tour to get the most out of Samebug.

Tired of useless tips?

Automated exception search integrated into your IDE

Root Cause Analysis

  1. com.mongodb.MongoException

    not talking to master and retries used up

    at com.mongodb.DBTCPConnector.call()
  2. MongoDB Java Driver
    DBCursor.hasNext
    1. com.mongodb.DBTCPConnector.call(DBTCPConnector.java:227)
    2. com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229)
    3. com.mongodb.DBTCPConnector.call(DBTCPConnector.java:229)
    4. com.mongodb.DBApiLayer$MyCollection.__find(DBApiLayer.java:295)
    5. com.mongodb.DBCursor._check(DBCursor.java:354)
    6. com.mongodb.DBCursor._hasNext(DBCursor.java:484)
    7. com.mongodb.DBCursor.hasNext(DBCursor.java:509)
    7 frames
  3. blueeyes.persistence.mongo
    RealDatabaseCollection$$anon$1.hasNext
    1. blueeyes.persistence.mongo.RealDatabaseCollection$$anon$1.hasNext(RealMongoImplementation.scala:82)
    1 frame
  4. Scala
    IterableLike$class.isEmpty
    1. scala.collection.IterableLike$class.isEmpty(IterableLike.scala:92)
    1 frame
  5. blueeyes.persistence.mongo
    IterableViewImpl.isEmpty
    1. blueeyes.persistence.mongo.IterableViewImpl.isEmpty(RealMongoImplementation.scala:122)
    1 frame
  6. Scala
    TraversableLike$class.headOption
    1. scala.collection.TraversableLike$class.headOption(TraversableLike.scala:483)
    1 frame
  7. blueeyes.persistence.mongo
    MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply
    1. blueeyes.persistence.mongo.IterableViewImpl.headOption(RealMongoImplementation.scala:122)
    2. blueeyes.persistence.mongo.QueryBehaviours$SelectOneQueryBehaviour$class.query(QueryBehaviours.scala:128)
    3. blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71)
    4. blueeyes.persistence.mongo.MongoSelectOneQuery.query(MongoQuery.scala:71)
    5. blueeyes.persistence.mongo.QueryBehaviours$MongoQueryBehaviour$class.apply(QueryBehaviours.scala:16)
    6. blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71)
    7. blueeyes.persistence.mongo.MongoSelectOneQuery.apply(MongoQuery.scala:71)
    8. blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:46)
    9. blueeyes.persistence.mongo.MongoDatabase$$anonfun$blueeyes$persistence$mongo$MongoDatabase$$mongoActor$1.apply(Mongo.scala:43)
    9 frames
  8. blueeyes.concurrent
    ActorImplementationMultiThreaded$StrategyWorker.run
    1. blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14$$anonfun$submit$1.apply(Actor.scala:17)
    2. blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:50)
    3. blueeyes.concurrent.Future$$anonfun$deliver$1.apply(Future.scala:46)
    4. blueeyes.concurrent.ReadWriteLock$class.writeLock(ReadWriteLock.scala:10)
    5. blueeyes.concurrent.Future$$anon$1.writeLock(Future.scala:22)
    6. blueeyes.concurrent.Future.deliver(Future.scala:45)
    7. blueeyes.concurrent.ActorExecutionStrategySequential$$anon$14.submit(Actor.scala:17)
    8. blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker$$anonfun$run$1.apply$mcV$sp(Actor.scala:195)
    9. blueeyes.concurrent.ActorImplementationMultiThreaded$ActorContext$.withActorFn(Actor.scala:230)
    10. blueeyes.concurrent.ActorImplementationMultiThreaded$StrategyWorker.run(Actor.scala:189)
    10 frames