Isso ocorre devido a tempos limite de conexão. Os problemas estão sendo rastreados aqui
Estou testando um failover do conjunto de réplicas do MongoDB de produção. Quando falho manualmente em uma das instâncias, vejo um aprox. Diminuição de 1000x (mil x) em tempos de resposta de minhas consultas PHP.
Estou no mais recente MongoDB (2.2.2) e no driver mais recente do php (1.3.3). Eu tenho um conjunto de réplica de 3 servidores e um teste de php que faz duas chamadas idênticas de volta para trás.
Alguém mais viu isso? Alguém pode sugerir uma alteração na minha configuração para corrigi-lo? É um problema de parada para mim.
Detalhes abaixo ... Nota: Eu não estou falhando o PRIMÁRIO Estou com um teste SECUNDÁRIO mas anedótico indica que não faz nenhuma diferença.
Muito obrigado por qualquer informação que você possa fornecer.
-- 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 ...
Eu anexei alguns logs detalhados do driver mongo-php (abaixo, podado e redigido um pouco para encaixar tudo). Parece que o driver tenta verificar todos os servidores replicaSet várias vezes. Se um servidor não estiver disponível, ele atingirá um tempo limite de 1000 ms. Parece que esses são os prováveis culpados pelo grande aumento no tempo de resposta. Eu estou olhando para um bug no driver ou "funciona como projetado"? Se é por design, então parece que replicaSets e php não são uma boa mistura? Meu site cai quando atingido por um aumento tão grande para cada consulta. Devo evitar dizer ao php sobre todos os servidores de conjuntos de réplicas e apenas dar ao construtor MongoClient o PRIMARY? Isso não parece que vai voar também.
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 ...
O PHP Mongo Driver 1.4.0 corrigiu esse problema.
Veja o log de alterações: link