Secondary server tries to sync with unavailable server

[Lukas Krecan]

We are trying to simulate network split (partition) on a Mongo 2.0.2
replica set consisting of three nodes. Basically we DROP all packets
between PRIMARY and SLAVES.

PRIMARY = lk-mm1
SECONDARY1 = lk-mm2
SECONDARY2 = lk-mm4

On primary:

iptables -A INPUT --src lk-mm4 -j DROP
iptables -A OUTPUT --dst lk-mm4 -j DROP
iptables -A INPUT --src lk-mm2 -j DROP
iptables -A OUTPUT --dst lk-mm2 -j DROP

The primary server correctly steps down, one of the secondaries
becomes master.

The problem is that the other secondary still tries to read oplog from
the late PRIMARY.

Thu Feb 9 14:07:34 [rsSync] replSet syncing to: lk-mm1:27017
Thu Feb 9 14:08:12 [rsHealthPoll] DBClientCursor::init call() failed
Thu Feb 9 14:08:12 [rsHealthPoll] replSet info lk-mm1:27017 is down
(or slow to respond): DBClientBase::findN: transport error: lk-
mm1:27017 query: { replSetHeartbeat: "gdc", v: 3, pv: 1, checkEmpty:
false, from: "lk-mm2:27017" }
Thu Feb 9 14:08:12 [rsHealthPoll] replSet member lk-mm1:27017 is now
in state DOWN
Thu Feb 9 14:08:12 [rsMgr] not electing self, lk-mm4:27017 would veto
Thu Feb 9 14:08:12 [conn597] replSet info voting yea for lk-mm4:27017
(2)
Thu Feb 9 14:08:13 [rsHealthPoll] replSet member lk-mm4:27017 is now
in state PRIMARY
Thu Feb 9 14:08:24 [rsHealthPoll] couldn't connect to lk-mm1:
couldn't connect to server lk-mm1:27017
Thu Feb 9 14:11:34 [rsHealthPoll] couldn't connect to lk-mm1:27017:
couldn't connect to server lk-mm1:27017

Since we are using writeConcern = 2 the replica set does not accept
any writes. I would expect, that the secondary will try to read the
oplog from the new primary. Can we somehow change the configuration to
make it work? Or is it a bug?

[Scott Hernandez]

Nothing here looks wrong. The [rsHealthPoll] are not directly related
to oplog replication but are part of the health check which is
required for every member to run against every other member in the
set.

Is there some reason you think replication has stopped?

When you use W=2 it always does this from the primary, where you are
writing. The primary will block on that client connection until the
requirement is satisfied (one other replica has caught up to that
write).

> --
> You received this message because you are subscribed to the Google Groups "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com.
> To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.
>

[Lukas Krecan]

Well it eventually starts working (after ~15 minutes). Would it be
possible to make the timeout shorter?

Thu Feb 9 14:08:24 [rsHealthPoll] couldn't connect to lk-mm1:27017:

couldn't connect to server lk-mm1:27017
Thu Feb 9 14:11:34 [rsHealthPoll] couldn't connect to lk-mm1:27017:
couldn't connect to server lk-mm1:27017

Thu Feb 9 14:14:44 [rsHealthPoll] couldn't connect to lk-mm1:27017:

couldn't connect to server lk-mm1:27017

Thu Feb 9 14:17:54 [rsHealthPoll] couldn't connect to lk-mm1:27017:

couldn't connect to server lk-mm1:27017

Thu Feb 9 14:21:04 [rsHealthPoll] couldn't connect to lk-mm1:27017:

couldn't connect to server lk-mm1:27017

Thu Feb 9 14:24:14 [rsHealthPoll] couldn't connect to lk-mm1:27017:

couldn't connect to server lk-mm1:27017

Thu Feb 9 14:24:15 [rsSync] Socket recv() errno:110 Connection timed
out 10.244.123.13:27017
Thu Feb 9 14:24:15 [rsSync] SocketException: remote:
10.244.123.13:27017 error: 9001 socket exception [1] server
[10.244.123.13:27017]
Thu Feb 9 14:24:15 [rsSync] Socket flush send() errno:32 Broken pipe
10.244.123.13:27017
Thu Feb 9 14:24:15 [rsSync] caught exception (socket exception) in
destructor (~PiggyBackData)
Thu Feb 9 14:24:15 [rsSync] replSet syncThread: 10278 dbclient error
communicating with server: lk-mm1:27017
Thu Feb 9 14:24:26 [rsSync] replSet syncing to: lk-mm4:27017

[Lukas Krecan]

Thanks for your fast response. From the db.printSlaveReplicationInfo()
I see that the secondary server is not updated. After ~15 minutes I
see "[rsSync] Socket recv() errno:110 Connection timed
out 10.244.123.13:27017 " (see my next mail) and after that the
secondary starts fetching data from the new primary. I do not like the
fact that it takes 15 minutes. Thanks again

[Scott Hernandez]

It is based around the conditions you are generating. If you reject
rather than black-hole traffic does it respond more quickly? I suspect
it is waiting on the socket timeout/close from the OS.

You can reduce the time the OS waits to close sockets, or enable
keep-alives (with a lower timeout).

[Lukas Krecan]

I see, so it is not possible to set the timeout in Mongo itself. Do
you think that it would make sense to add such configuration option to
Mongo?

[Scott Hernandez]

Sure, go ahead and file a feature request for an explicit timeout for
the oplog reader; it would make sense to put a limit of 30s since that
should be max time it is should take the server to respond on a
await+tailable cursor.

http://jira.mongodb.org/browse/SERVER

[Lukas Krecan]

Created https://jira.mongodb.org/browse/SERVER-4918