MongoDB副本集故障切换会增加1000倍的查询响应时间

我正在testing一个生产MongoDB副本集故障转移。 当我手动失败的情况下，我看到一个约。 我的PHP查询的响应时间减less了1000倍（一千次）。

我在最新的MongoDB（2.2.2）和最新的PHP驱动程序（1.3.3）。 我有一个3服务器副本集和一个PHPtesting，使两个相同的调用背靠背。

有没有人看过这个？ 有人可以build议我的configuration更改来解决它吗？ 这对我来说是一个停滞的问题。

下面的细节…注：我没有失败的主要我失败了一个次要的，但轶事testing表明，它没有任何区别。

• 有3个生产节点，为什么Mongodb会抱怨投票节点？
• “无法创buildIPv6套接字”postgresql备用错误
• testingActive Directory架构修改（不升级）
• 我是否需要在每个mongod上运行db.repairDatabase（）？
• Tomcat不会复制会话属性

非常感谢您提供的任何见解。

-- ReplicaSet Config test:PRIMARY> rs.conf() { "_id" : "test", "version" : 10, "members" : [ { "_id" : 1, "host" : "10.0.1.1:27017", "priority" : 20 }, { "_id" : 2, "host" : "10.0.3.3:27017", "priority" : 10 }, { "_id" : 3, "host" : "10.0.2.2:27017" } ] } -- ReplicaSet status when everything is working (eg I don't firewall off a SECONDARY) test:PRIMARY> rs.status() { "set" : "test", "date" : ISODate("2013-01-24T16:32:14Z"), "myState" : 1, "members" : [ { "_id" : 1, "name" : "10.0.1.1:27017", "health" : 1, "state" : 1, "stateStr" : "PRIMARY", "uptime" : 1704, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "self" : true }, { "_id" : 2, "name" : "10.0.3.3:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 14, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "lastHeartbeat" : ISODate("2013-01-24T16:32:14Z"), "pingMs" : 1511 }, { "_id" : 3, "name" : "10.0.2.2:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 1698, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "lastHeartbeat" : ISODate("2013-01-24T16:32:14Z"), "pingMs" : 1 } ], "ok" : 1 } -- ReplicaSet status when I firewall off SECONDARY 10.0.3.3 test:PRIMARY> rs.status() { "set" : "test", "date" : ISODate("2013-01-24T16:27:30Z"), "myState" : 1, "members" : [ { "_id" : 1, "name" : "10.0.1.1:27017", "health" : 1, "state" : 1, "stateStr" : "PRIMARY", "uptime" : 1420, "optime" : Timestamp(1359044238000, 1), "optimeDate" : ISODate("2013-01-24T16:17:18Z"), "self" : true }, { "_id" : 2, "name" : "10.0.3.3:27017", "health" : 0, "state" : 8, "stateStr" : "(not reachable/healthy)", "uptime" : 0, "optime" : Timestamp(1359042361000, 1), "optimeDate" : ISODate("2013-01-24T15:46:01Z"), "lastHeartbeat" : ISODate("2013-01-24T16:15:47Z"), "pingMs" : 0, "errmsg" : "socket exception [CONNECT_ERROR] for 10.0.3.3:27017" }, { "_id" : 3, "name" : "10.0.2.2:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 1414, "optime" : Timestamp(1359044238000, 1), "optimeDate" : ISODate("2013-01-24T16:17:18Z"), "lastHeartbeat" : ISODate("2013-01-24T16:27:30Z"), "pingMs" : 1 } ], "ok" : 1 } -- log snippet of activity between identical queries BEFORE manual failure of SECONDARY Thu Jan 24 08:12:42 [conn50] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:29 reslen:163 0ms Thu Jan 24 08:12:42 [initandlisten] connection accepted from 10.0.0.123:60710 #51 (13 connections now open) Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { getnonce: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { getnonce: 1 } ntoreturn:1 keyUpdates:0 reslen:65 0ms Thu Jan 24 08:12:42 [conn51] run command mydb.$cmd { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:12:42 [conn51] authenticate db: mydb { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:12:42 [conn51] command mydb.$cmd command: { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } ntoreturn:1 keyUpdates:0 locks(micros) r:48 reslen:91 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { ping: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { ping: 1 } ntoreturn:1 keyUpdates:0 reslen:37 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:12:42 [conn51] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:19 reslen:163 0ms -- log snippet of activity between identical queries AFTER manual failure of SECONDARY Thu Jan 24 08:17:12 [conn66] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:32 reslen:163 0ms Thu Jan 24 08:17:12 [initandlisten] connection accepted from 10.0.0.123:60719 #68 (13 connections now open) Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { getnonce: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { getnonce: 1 } ntoreturn:1 keyUpdates:0 reslen:65 0ms Thu Jan 24 08:17:12 [conn68] run command mydb.$cmd { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:17:12 [conn68] authenticate db: mydb { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:17:12 [conn68] command mydb.$cmd command: { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } ntoreturn:1 keyUpdates:0 locks(micros) r:87 reslen:91 0ms Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { ping: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { ping: 1 } ntoreturn:1 keyUpdates:0 reslen:37 0ms Thu Jan 24 08:17:13 BackgroundJob starting: ConnectBG Thu Jan 24 08:17:13 [conn68] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:17:13 [conn68] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:17:14 [conn67] run command admin.$cmd { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } Thu Jan 24 08:17:14 [conn67] command admin.$cmd command: { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } ntoreturn:1 keyUpdates:0 reslen:120 0ms Thu Jan 24 08:17:14 [conn5] getmore local.oplog.rs query: { ts: { $gte: new Date(5837042494373625857) } } cursorid:220712315271329417 ntoreturn:0 keyUpdates:0 locks(micros) r:114 nreturned:0 reslen:20 5010ms Thu Jan 24 08:17:16 [conn67] run command admin.$cmd { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } Thu Jan 24 08:17:16 [conn67] command admin.$cmd command: { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } ntoreturn:1 keyUpdates:0 reslen:120 0ms Thu Jan 24 08:17:16 [conn68] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:33 reslen:163 0ms - Elapse time for PHP test BEFORE manual failure of SECONDARY - Note: ReadPreference = MongoClient::RP_PRIMARY, WriteConcern = 1 0.0052609444s - Elapse time for PHP test AFTER manual failure of SECONDARY - Note: ReadPreference = MongoClient::RP_PRIMARY, WriteConcern = 1 4.0203089714s 

更新中…

我已经附加了一些来自mongo-php驱动程序的详细日志（下面，修剪和编辑有点适合所有）。 看起来像驱动程序试图多次validation所有replicaSet服务器。 如果一个服务器不可用，它会遇到1000毫秒的超时。 似乎这些是可能的大反应时间增加的罪魁祸首。 我正在查看驱动程序中的错误还是“按devise工作”？ 如果是通过devise，那么似乎replicaSets和PHP是不是一个好的组合？ 当我的网站遇到如每个查询的巨大增加时，跌倒。 我应该避免告诉PHP所有的副本集服务器，只给MongoClient构造函数的主要？ 这似乎也不会飞。

 8:14 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:14 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/r/redacted-id;23623 (looking for 10.0.1.1:27017;test;main/r/redacted-id;23623) in ... 8:14 Notice: CON FINE: is_ping: skipping: last ran at 1359076091, now: 1359076094, time left: 2 in ... 8:14 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/r/redacted-id;23623 (looking for 10.0.2.2:27017;test;main/r/redacted-id;23623) in ... 8:14 Notice: CON FINE: is_ping: skipping: last ran at 1359076091, now: 1359076094, time left: 2 in ... 8:14 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:15 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:15 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/r/redacted-id;23623 (looking for 10.0.1.1:27017;test;main/r/redacted-id;23623) in ... 8:15 Notice: CON FINE: ismaster: skipping: last ran at 1359076092, now: 1359076095, time left: 12 in ... 8:15 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/r/redacted-id;23623 (looking for 10.0.2.2:27017;test;main/r/redacted-id;23623) in ... 8:15 Notice: CON FINE: ismaster: skipping: last ran at 1359076093, now: 1359076095, time left: 13 in ... 8:15 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: finding candidate servers in ... 8:15 Notice: REPLSET FINE: - all servers in ... 8:15 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: filter_connections: done in ... 8:15 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:15 Notice: REPLSET FINE: limiting by credentials in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: limiting by credentials: done in ... 8:15 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: sorting servers: done in ... 8:15 Notice: REPLSET FINE: selecting near servers in ... 8:15 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: selecting near server: done in ... 8:15 Notice: REPLSET INFO: pick server: random element 0 in ... 8:15 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: IO FINE: getting reply in ... 8:15 Notice: IO FINE: getting cursor header in ... 8:15 Notice: IO FINE: getting cursor body in ... 8:15 Notice: PARSE INFO: Parsing mongodb://rw:[email protected],10.0.3.3/main in ... 8:15 Notice: PARSE INFO: - Found user 'rw' and a password in ... 8:15 Notice: PARSE INFO: - Found node: 10.0.1.1:27017 in ... 8:15 Notice: PARSE INFO: - Found node: 10.0.3.3:27017 in ... 8:15 Notice: PARSE INFO: - Connection type: MULTIPLE in ... 8:15 Notice: PARSE INFO: - Found database name 'main' in ... 8:15 Notice: PARSE INFO: - Found option 'readPreference': 'primary' in ... 8:15 Notice: PARSE INFO: - Found option 'w': 1 in ... 8:15 Notice: PARSE INFO: - Found option 'replicaSet': 'test' in ... 8:15 Notice: PARSE INFO: - Switching connection type: REPLSET in ... 8:15 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:15 Notice: CON INFO: connection_create: creating new connection for 10.0.1.1:27017 in ... 8:15 Notice: CON INFO: get_server_flags: start in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 239 in ... 8:15 Notice: CON FINE: get_server_flags: setting maxBsonObjectSize to 16777216 in ... 8:15 Notice: CON INFO: get_connection_single: authenticating 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:15 Notice: CON INFO: getnonce: start in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 45 in ... 8:15 Notice: CON FINE: getnonce: found nonce 'd4017c7d0ebc1a9c' in ... 8:15 Notice: CON INFO: authenticate: start in ... 8:15 Notice: CON FINE: authenticate: hash=md5(rw:mongo:thisisntreallytheacctpassword) = 65917a6cb23196fc6ba826e6fdf4b5e7 in ... 8:15 Notice: CON FINE: authenticate: key=md5(d4017c7d0ebc1a9crw65917a6cb23196fc6ba826e6fdf4b5e7) = 775bf2c6a18a3375086b66a430daf89b in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 71 in ... 8:15 Notice: CON INFO: authentication successful in ... 8:15 Notice: CON INFO: is_ping: pinging 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 17 in ... 8:15 Notice: CON INFO: is_ping: last pinged at 1359076095; time: 0ms in ... 8:15 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:16 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:16 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:16 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:16 Notice: CON INFO: ismaster: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 239 in ... 8:16 Notice: CON FINE: ismaster: the server name matches what we thought it'd be (10.0.1.1:27017). in ... 8:16 Notice: CON FINE: ismaster: the found replicaset name matches the expected one (test). in ... 8:16 Notice: CON INFO: ismaster: set name: test, ismaster: 1, secondary: 0, is_arbiter: 0 in ... 8:16 Notice: CON INFO: found host: 10.0.1.1:27017 in ... 8:16 Notice: CON INFO: found host: 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: found host: 10.0.3.3:27017 in ... 8:16 Notice: CON INFO: ismaster: last ran at 1359076096 in ... 8:16 Notice: CON FINE: discover_topology: ismaster worked in ... 8:16 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:16 Notice: CON INFO: discover_topology: found new host: 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: connection_create: creating new connection for 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: get_server_flags: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 239 in ... 8:16 Notice: CON FINE: get_server_flags: setting maxBsonObjectSize to 16777216 in ... 8:16 Notice: CON INFO: get_connection_single: authenticating 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON INFO: getnonce: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 45 in ... 8:16 Notice: CON FINE: getnonce: found nonce '19d9c5199e884edb' in ... 8:16 Notice: CON INFO: authenticate: start in ... 8:16 Notice: CON FINE: authenticate: hash=md5(rw:mongo:thisisntreallytheacctpassword) = 65917a6cb23196fc6ba826e6fdf4b5e7 in ... 8:16 Notice: CON FINE: authenticate: key=md5(19d9c5199e884edbrw65917a6cb23196fc6ba826e6fdf4b5e7) = 7fffb7f867a0e981952a45191fcab3f2 in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 71 in ... 8:16 Notice: CON INFO: authentication successful in ... 8:16 Notice: CON INFO: is_ping: pinging 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 17 in ... 8:16 Notice: CON INFO: is_ping: last pinged at 1359076096; time: 1ms in ... 8:16 Notice: CON INFO: discover_topology: found new host: 10.0.3.3:27017 in ... 8:16 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:17 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:17 Notice: CON WARN: discover_topology: could not connect to new host: 10.0.3.3:27017: Timed out after 1000 ms in ... 8:17 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:17 Notice: CON INFO: ismaster: start in ... 8:17 Notice: CON FINE: send_packet: read from header: 36 in ... 8:17 Notice: CON FINE: send_packet: data_size: 239 in ... 8:17 Notice: CON FINE: ismaster: the server name matches what we thought it'd be (10.0.2.2:27017). in ... 8:17 Notice: CON FINE: ismaster: the found replicaset name matches the expected one (test). in ... 8:17 Notice: CON INFO: ismaster: set name: test, ismaster: 0, secondary: 1, is_arbiter: 0 in ... 8:17 Notice: CON INFO: found host: 10.0.2.2:27017 in ... 8:17 Notice: CON INFO: found host: 10.0.3.3:27017 in ... 8:17 Notice: CON INFO: found host: 10.0.1.1:27017 in ... 8:17 Notice: CON INFO: ismaster: last ran at 1359076097 in ... 8:17 Notice: CON FINE: discover_topology: ismaster worked in ... 8:17 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:17 Notice: CON INFO: discover_topology: found new host: 10.0.3.3:27017 in ... 8:17 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:18 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:18 Notice: CON WARN: discover_topology: could not connect to new host: 10.0.3.3:27017: Timed out after 1000 ms in ... 8:18 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:18 Notice: REPLSET FINE: finding candidate servers in ... 8:18 Notice: REPLSET FINE: - all servers in ... 8:18 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: filter_connections: done in ... 8:18 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:18 Notice: REPLSET FINE: limiting by credentials in ... 8:18 Notice: REPLSET FINE: - skipping '10.0.1.1:27017;test;main/r/redacted-id;23623', username didn't match ('r' vs 'rw') in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: limiting by credentials: done in ... 8:18 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: sorting servers: done in ... 8:18 Notice: REPLSET FINE: selecting near servers in ... 8:18 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: selecting near server: done in ... 8:18 Notice: REPLSET INFO: pick server: random element 0 in ... 8:18 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:18 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:18 Notice: CON FINE: is_ping: skipping: last ran at 1359076095, now: 1359076098, time left: 2 in ... 8:18 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:19 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:19 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:19 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: is_ping: skipping: last ran at 1359076096, now: 1359076099, time left: 2 in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: ismaster: skipping: last ran at 1359076096, now: 1359076099, time left: 12 in ... 8:19 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: ismaster: skipping: last ran at 1359076097, now: 1359076099, time left: 13 in ... 8:19 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:19 Notice: REPLSET FINE: finding candidate servers in ... 8:19 Notice: REPLSET FINE: - all servers in ... 8:19 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: filter_connections: done in ... 8:19 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:19 Notice: REPLSET FINE: limiting by credentials in ... 8:19 Notice: REPLSET FINE: - skipping '10.0.1.1:27017;test;main/r/redacted-id;23623', username didn't match ('r' vs 'rw') in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: limiting by credentials: done in ... 8:19 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: sorting servers: done in ... 8:19 Notice: REPLSET FINE: selecting near servers in ... 8:19 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: selecting near server: done in ... 8:19 Notice: REPLSET INFO: pick server: random element 0 in ... 8:19 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: IO FINE: getting reply in ... 8:19 Notice: IO FINE: getting cursor header in ... 8:19 Notice: IO FINE: getting cursor body in ...