[CSHARP-412] SlaveOk queries directed to RECOVERING instances Created: 19/Mar/12  Updated: 02/Apr/15  Resolved: 20/Mar/12

Status: Closed
Project: C# Driver
Component/s: None
Affects Version/s: 1.3.1
Fix Version/s: 1.4

Type: Bug Priority: Major - P3
Reporter: Aristarkh Zagorodnikov Assignee: Robert Stam
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified


 Description   

When one of our secondaries is resynced, it appears that C# driver sends slaveOk queries to it while it's still recovering.
There are several errors in the database log like this one:
Mon Mar 19 21:21:03 [conn328] assertion 13436 not master or secondary, can't read ns:d2_feed3.counters.car
And, of course, the query fails on the client side.



 Comments   
Comment by Aristarkh Zagorodnikov [ 20/Mar/12 ]

Good to know that you found out the reason, looking forward for the fix =)

Comment by Robert Stam [ 20/Mar/12 ]

Thanks so much for repeating the test and providing the additional information. It is very useful.

In the reply to isMaster we see:

{
isMaster : false,
secondary : false
}

which we expect, because even though the new member is a secondary the server has been coded to return

{ secondary : false }

when a secondary is in recovering mode.

So normally the C# driver would not have sent queries to this secondary until it was done with the initial sync, at which point the server would start returning

{ secondary : true }

.

But what's different in this scenario is that this secondary has also been configured as a passive secondary, which we can see from the

{ passive : true }

in the response to isMaster.

All drivers consider passive secondaries as eligible to receive slaveOk queries, so my theory is that the C# driver is sending queries to this secondary not because of

{ secondary : true }

, but because of

{ passive : true }

.

I've experimented with a local replica set and it looks like isMaster returns

{ secondary : true }

even for passive members (but not until they are out of recovery mode), so it looks like all we need to do is remove the check for IsPassive from the driver when it is choosing which secondary to send a slaveOk query to, since passives will already be eligible due to

{ secondary : true }

.

I will try and find out if in earlier versions of the server it was returning

{ secondary : false }

for passives, but I suspect it was not and that it was just an invalid assumption on my part that the algorithm that distributes slaveOk queries to secondaries had to check the IsPassive flag also.

Comment by Aristarkh Zagorodnikov [ 20/Mar/12 ]

It appears that it's related to cursors:
MongoDB.Driver.MongoQueryException: QueryFailure flag was not master or secondary, can't read (response was

{ "$err" : "not master or secondary, can't read", "code" : 13436 }

).
at MongoDB.Driver.Internal.MongoReplyMessage`1.ReadFrom(BsonBuffer buffer, IBsonSerializationOptions serializationOptions) in Driver\Internal\MongoReplyMessage.cs:line 102
at MongoDB.Driver.Internal.MongoConnection.ReceiveMessage[TDocument](BsonBinaryReaderSettings readerSettings, IBsonSerializationOptions serializationOptions) in Driver\Internal\MongoConnection.cs:line 435
at MongoDB.Driver.MongoCursorEnumerator`1.GetReply(MongoConnection connection, MongoRequestMessage message) in Driver\Core\MongoCursorEnumerator.cs:line 296
at MongoDB.Driver.MongoCursorEnumerator`1.GetFirst() in Driver\Core\MongoCursorEnumerator.cs:line 253
at MongoDB.Driver.MongoCursorEnumerator`1.MoveNext() in Driver\Core\MongoCursorEnumerator.cs:line 141
at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)

Comment by Aristarkh Zagorodnikov [ 20/Mar/12 ]

Yes, it repeats.
isMaster returns the following:
{
"setName" : "drive2",
"ismaster" : false,
"secondary" : false,
"hosts" : [
"l1-1.sheratan.bru:27017"
],
"passives" : [
"l1-1.shaula.bru:27017"
],
"arbiters" : [
"l1-1.perseus.bru:27017"
],
"primary" : "l1-1.sheratan.bru:27017",
"passive" : true,
"me" : "l1-1.shaula.bru:27017",
"maxBsonObjectSize" : 16777216,
"ok" : 1
}

Comment by Robert Stam [ 19/Mar/12 ]

Is this a test that you can repeat? I'm curious to know what that replica set member was sending back in response to the isMaster command during the time is was doing the initial sync. It looks like it must have been sending back

{ secondary: true }

the whole time it was doing the initial sync. If that's the case this might be considered a server bug.

Alternatively, the driver could follow up the isMaster command with a second call to replSetGetStatus (which is the only way to get the actual status of the replica set member), which would be somewhat detrimental in that it's a second network round trip (but it does only happen once every 10 seconds).

I grepped the other drivers and none of them are calling replSetGetStatus.

Comment by Aristarkh Zagorodnikov [ 19/Mar/12 ]

I'll give you an extract of the log to give you proper impressions of timings.
\e start empty replica slave:
Mon Mar 19 21:17:45 [initandlisten] MongoDB starting : pid=13154 port=27017 dbpath=/mnt/disk3/mongodb 64-bit host=shaula
Mon Mar 19 21:17:45 [initandlisten] db version v2.0.2, pdfile version 4.5
Mon Mar 19 21:17:45 [initandlisten] git version: 514b122d308928517f5841888ceaa4246a7f18e3
Mon Mar 19 21:17:45 [initandlisten] build info: Linux bs-linux64.10gen.cc 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Mon Mar 19 21:17:45 [initandlisten] options:

{ bind_ip: "l1-1.shaula.bru,c1.shaula.bru,127.0.0.1", config: "/etc/mongodb.conf", dbpath: "/mnt/disk3/mongodb", directoryperdb: "true", logappend: "true", logpath: "/var/log/mongodb/mongodb.log", noauth: "true", noprealloc: "true", replSet: "drive2", rest: "true", slowms: 500, smallfiles: "true" }

Mon Mar 19 21:17:45 [initandlisten] journal dir=/mnt/disk3/mongodb/journal
Mon Mar 19 21:17:45 [initandlisten] recover : no journal files present, no recovery needed
Mon Mar 19 21:17:45 [initandlisten] preallocateIsFaster=true 2.22
Mon Mar 19 21:17:45 [rsStart] couldn't connect to localhost:27017: couldn't connect to server localhost:27017
Mon Mar 19 21:17:45 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Mon Mar 19 21:17:45 [rsStart] replSet info you may need to run replSetInitiate – rs.initiate() in the shell – if that is not already done
Mon Mar 19 21:17:45 [websvr] admin web console waiting for connections on port 28017
Mon Mar 19 21:17:45 [initandlisten] waiting for connections on port 27017
...
It finds replication partners:
Mon Mar 19 21:17:55 [rsStart] trying to contact l1-1.perseus.bru:27017
Mon Mar 19 21:17:55 [rsStart] trying to contact l1-1.sheratan.bru:27017
Mon Mar 19 21:17:55 [rsStart] replSet got config version 7 from a remote, saving locally
Mon Mar 19 21:17:55 [rsStart] replSet info saving a newer config version to local.system.replset
Mon Mar 19 21:17:55 [FileAllocator] allocating new datafile /mnt/disk3/mongodb/local/local.ns, filling with zeroes...
Mon Mar 19 21:17:55 [FileAllocator] done allocating datafile /mnt/disk3/mongodb/local/local.ns, size: 16MB, took 0.001 secs
Mon Mar 19 21:17:55 [FileAllocator] allocating new datafile /mnt/disk3/mongodb/local/local.0, filling with zeroes...
Mon Mar 19 21:17:55 [FileAllocator] done allocating datafile /mnt/disk3/mongodb/local/local.0, size: 16MB, took 0.001 secs
Mon Mar 19 21:17:55 [rsStart] replSet saveConfigLocally done
Mon Mar 19 21:17:55 [rsStart] replSet STARTUP2
Mon Mar 19 21:17:55 [rsSync] ******
Mon Mar 19 21:17:55 [rsSync] creating replication oplog of size: 2943MB...
...
We start receiving these:
Mon Mar 19 21:17:57 [conn4] assertion 13436 not master or secondary, can't read ns:d2_feed3.counters.car query:

{ _id: -3735451117392232444 }

...
This is the last one (15 minutes after the first one, 1037 "assert 13436" lines later)
Mon Mar 19 21:33:37 [conn2085] assertion 13436 not master or secondary, can't read ns:d2_visits.guests query:{ $query: { _id.u: 288
230376151887937, t:

{ $gte: new Date(1329508800000) }

}, $orderby:

{ t: -1 }

}
...
Initial sync completed:
Mon Mar 19 21:35:03 [rsSync] replSet initial sync done
Mon Mar 19 21:35:04 [initandlisten] connection accepted from 10.1.1.21:54748 #2166
Mon Mar 19 21:35:04 [rsSync] replSet syncing to: l1-1.sheratan.bru:27017
Mon Mar 19 21:35:04 [rsSync] replSet SECONDARY

Comment by Robert Stam [ 19/Mar/12 ]

When a secondary is in recovering state it should be report

{ secondary: false }

in the response to isMaster (see SERVER-3459), which is what keeps the driver from sending queries to secondaries in recovering mode.

Is this just a timing issue? The members of the replica set are polled once every 10 seconds, so it might take the driver a few seconds to detect that a secondary has gone into recovering mode.

Would that explain what you are seeing?

Generated at Wed Feb 07 21:36:45 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.