I'm testing a production MongoDB replica set failover. When I manually fail one of the instances I see an approx. 1000x (one thousand x) decrease in response times of my PHP queries.
I'm on the latest MongoDB (2.2.2) and the latest php driver (1.3.3). I've got a 3 server replica set and a php test that makes two identical calls back to back.
Has anyone else seen this? Can someone suggest a change in my configuration to fix it? It's a stop-ship issue for me.
Details below... Note: I'm not failing the PRIMARY I'm failing a SECONDARY but anecdotal testing indicates it doesn't make any difference.
Many thanks for whatever insight you can provide.
-- 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 (e.g. 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
UPDATE...
I've attached some verbose logs from the mongo-php driver (below, pruned and redacted somewhat to fit it all in). Looks like the driver tries to verify all replicaSet servers multiple times. If a server is unavailable it hits a 1000ms timeout. Seems like these are the likely culprits in the large response time increase. Am I looking at a bug in the driver or "works as designed"? If it is by design then it seems like replicaSets and php are not a good mix? My site falls down when hit by such as huge increase to every query. Should I avoid telling php about all the replica set servers and just give the MongoClient constructor the PRIMARY? That doesn't seem like it will fly either.
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 ...
