ReplicaSet configuration for reads/writes
689 views
Skip to first unread message
Nik Kolev
Oct 25, 2012, 5:39:25 PM10/25/12
to mongodb...@googlegroups.com
Environment:
- host: Windows 7
- mongod: v2.2 (mongodb-win32-x86_64-2008plus-2.2.0)
- mongo setup: 3 mongod processes running on the same host in a replica set, 2 real and 1 arbiter
- csharp driver: v.1.6.0.4624
I create a MongoServer by providing a MongoServerSetings with the following properties:
- SafeMode = SafeMode.True
- Servers = a collecttion of all 3 mongods' MongoServerAddress-es
- ReadPreference = PrimaryPrefered
I have a function that asks the MongoServer for a collection (MongoCollection) of a database, first does a read on the collection and then attempts to do a write. The read succeeds but the write fails with the following stack trace (wrapped as JSON doc as Mongo in this case is backing a web service - please excuse the ugliness):
===
{"responseStatus":{"errorCode":"MongoSafeModeException","message":"Safemode detected an error 'not master'. (Response was { \"err\" : \"not master\", \"code\" : 10056, \"n\" : 0, \"lastOp\" : { \"$timestamp\" : NumberLong(0) }, \"connectionId\" : 1569, \"ok\" : 1.0 }).","stackTrace":"[ById: 10/25/2012 8:53:40 PM]:\n[REQUEST: {id:1}]MongoDB.Driver.MongoSafeModeException: Safemode detected an error 'not master'. (Response was { \"err\" : \"not master\", \"code\" : 10056, \"n\" : 0, \"lastOp\" : { \"$timestamp\" : NumberLong(0) }, \"connectionId\" : 1569, \"ok\" : 1.0 }).\r\n at MongoDB.Driver.Internal.MongoConnection.SendMessage(MongoRequestMessage message, SafeMode safeMode, String databaseName) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Internal\\MongoConnection.cs:line 549\r\n at MongoDB.Driver.MongoCollection.Remove(IMongoQuery query, RemoveFlags flags, SafeMode safeMode) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Core\\MongoCollection.cs:line 1312\r\n at MongoDB.Driver.MongoCollection.Remove(IMongoQuery query) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Core\\MongoCollection.cs:line 1272
===
What's
Guessing here the collection when initially obtained was backed by a connection to the slave replica and that's why the read succeeded but the write did not. If that's the case how would one use the driver for such scenarios?
Moreover, going with my guess I changed the read preference to Primary (just Primary). Then even more weirdness happened. I got an exception even before the write was attempted, but when the function was trying to do the read:
===
{"responseStatus":{"errorCode":"MongoQueryException","message":"QueryFailure flag was not master and slaveOk=false (response was { \"$err\" : \"not master and slaveOk=false\", \"code\" : 13435 }).","stackTrace":"[ById: 10/25/2012 9:05:30 PM]:\n[REQUEST: {id:1}]MongoDB.Driver.MongoQueryException: QueryFailure flag was not master and slaveOk=false (response was { \"$err\" : \"not master and slaveOk=false\", \"code\" : 13435 }).\r\n at MongoDB.Driver.Internal.MongoReplyMessage`1.ReadFrom(BsonBuffer buffer, IBsonSerializationOptions serializationOptions) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Internal\\MongoReplyMessage.cs:line 99\r\n at MongoDB.Driver.Internal.MongoConnection.ReceiveMessage[TDocument](BsonBinaryReaderSettings readerSettings, IBsonSerializationOptions serializationOptions) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Internal\\MongoConnection.cs:line 475\r\n at MongoDB.Driver.MongoCursorEnumerator`1.GetReply(MongoConnection connection, MongoRequestMessage message) in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Core\\MongoCursorEnumerator.cs:line 296\r\n at MongoDB.Driver.MongoCursorEnumerator`1.GetFirst() in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Core\\MongoCursorEnumerator.cs:line 253\r\n at MongoDB.Driver.MongoCursorEnumerator`1.MoveNext() in C:\\work\\rstam\\mongo-csharp-driver\\Driver\\Core\\MongoCursorEnumerator.cs:line 141
===
I see the error in the mongod's log (this is the SECONDARY mongod's log):
===
Thu Oct 25 22:05:30 [conn1665] assertion 13435 not master and slaveOk=false ns:mdm.policies query:{ ids: "1" }
Thu Oct 25 22:05:30 [conn1665] problem detected during query over mdm.policies : { $err: "not master and slaveOk=false", code: 13435 }
===
FWIW I don't see the first error I discussed captured in one shape or another in the mongod's logs - I checked in the logs for all 3 of my mongod processes.
I assumed that setting the ReadPreference to Primary would let the driver know that all connections need to be asked of the primary mongod. I guess that's not what happened here for me?
Ideas/Suggestions/Recs would be greatly appreciated.
Thanks, -nik
Robert Stam
Oct 26, 2012, 10:09:57 AM10/26/12
to mongodb...@googlegroups.com
In 1.6 it was possible for ReadPreference.PrimaryPreferred to use a Secondary even if the Primary was available if the primary's ping time was more than 15 ms slower than the primary. In 1.6.1 PrimaryPreferred will always use the Primary if possible, and only use a Secondary if there is no Primary (regardless of ping times). That could explain your first result.
The second result is harder to explain. It looks like you are connecting directly to a secondary, because the ReadPreference appears to be ignored, which only happens when connecting directly to a server.
Can you make sure you are actually connecting to the replica set in replica set mode? One way you could do that is to put a breakpoint on your call that is throwing the exception and checking the MongoServer.Instances property and reporting back how many entries the Instances array has and what the InstanceType is for each instance.
You could also check your MongoCursor.ReadPreference just before executing the query to verify that the cursor has the ReadPreference you wanted. In order to examine the cursor you might have to introduce an intermediate variable.
Let me know what you find and we can proceed from there.
Nik Kolev
Oct 26, 2012, 2:39:37 PM10/26/12
to mongodb...@googlegroups.com
Thanks Robert. I'll try to get to this in the next couple of hours. If I don't I'll send update with my findings on Monday.
Nik Kolev
Oct 30, 2012, 3:11:37 PM10/30/12
to mongodb...@googlegroups.com
OK. Couldn't get to it on Monday - it was Sandy times. Anyways after some breakpointing and messing with the status of the nodes in my replca set I am pretty sure I know what's going on.
- To recap my env, I have a 3-node replica set with 2 "real" nodes and 1 "arbiter". I am using a 1.6.0.4624 driver and a 2.2.0 mongo.
- The problem occurs with the same underlying reason regardless of whether the ReadPreference is Primary or PrimaryPreferred.
- The problem occurs when the first instance of the MongoServerAddress-es enumerable I am passing as the value to the Servers property of the MongoServerSettings the MongoServer is created with is the secondary mongod.
- In both readPreference cases, the Instances array of the MongoServer object contained just one MongoServerInstance which was pointing to the secondary mongod. The InstanceType was ReplicaSetMember. The ReplicaSetInformation was correctly identifying the replica set name, how many members there were in the replica set, and what the primary member was. I can post a screenshot of the state I am describing here later today (as certain things are blocked at w$rk).
Unfortunately things did not get better with the 1.6.1 version of the driver. The same issue exists there.
craiggwilson
Oct 30, 2012, 3:30:02 PM10/30/12
to mongodb...@googlegroups.com
Nik, can you provide us with the results of a db.isMaster call on each of the servers as well. Also, please run an rs.status() and send the results. These can both be run from the shell. This will tell us what the servers know about themselves.
Nik Kolev
Oct 30, 2012, 3:40:23 PM10/30/12
to mongodb...@googlegroups.com
Sure. Here are the results:
-- Status (I ran it on the secondary):
[v2.2.0@special199b:50000 (db:mdm) rs_1347997619:2=SECONDARY]> rs.status()
{
"set" : "rs_1347997619",
"date" : ISODate("2012-10-30T19:32:34Z"),
"myState" : 2,
"syncingTo" : "127.0.0.1:50001",
"members" : [
{
"_id" : 0,
"name" : "127.0.0.1:50000",
"health" : 1,
"state" : 2,
"stateStr" : "SECONDARY",
"uptime" : 5367,
"optime" : Timestamp(1351619758000, 1),
"optimeDate" : ISODate("2012-10-30T17:55:58Z"),
"self" : true
},
{
"_id" : 1,
"name" : "127.0.0.1:50001",
"health" : 1,
"state" : 1,
"stateStr" : "PRIMARY",
"uptime" : 5366,
"optime" : Timestamp(1351619758000, 1),
"optimeDate" : ISODate("2012-10-30T17:55:58Z"),
"lastHeartbeat" : ISODate("2012-10-30T19:32:32Z"),
"pingMs" : 0
},
{
"_id" : 2,
"name" : "127.0.0.1:50002",
"health" : 1,
"state" : 7,
"stateStr" : "ARBITER",
"uptime" : 5366,
"lastHeartbeat" : ISODate("2012-10-30T19:32:32Z"),
"pingMs" : 0
}
],
"ok" : 1
}
[v2.2.0@special199b:50000 (db:mdm) rs_1347997619:2=SECONDARY]>
-- isMaster (sec):
[v2.2.0@special199b:50000 (db:mdm) rs_1347997619:2=SECONDARY]> db.isMaster()
{
"setName" : "rs_1347997619",
"ismaster" : false,
"secondary" : true,
"hosts" : [
],
"arbiters" : [
],
"primary" : "127.0.0.1:50001",
"me" : "127.0.0.1:50000",
"maxBsonObjectSize" : 16777216,
"localTime" : ISODate("2012-10-30T19:32:18.836Z"),
"ok" : 1
}
-- isMaster (prim):
[v2.2.0@special199b:50001 (db:mdm) rs_1347997619:1=PRIMARY]> db.isMaster()
{
"setName" : "rs_1347997619",
"ismaster" : true,
"secondary" : false,
"hosts" : [
],
"arbiters" : [
],
"primary" : "127.0.0.1:50001",
"me" : "127.0.0.1:50001",
"maxBsonObjectSize" : 16777216,
"localTime" : ISODate("2012-10-30T19:38:56.265Z"),
"ok" : 1
}
[v2.2.0@special199b:50001 (db:mdm) rs_1347997619:1=PRIMARY]>
-- isMaster (arb):
[v2.2.0@special199b:50002 (db:mdm) rs_1347997619:7=ARBITER]> db.isMaster()
{
"setName" : "rs_1347997619",
"ismaster" : false,
"secondary" : false,
"hosts" : [
],
"arbiters" : [
],
"primary" : "127.0.0.1:50001",
"arbiterOnly" : true,
"me" : "127.0.0.1:50002",
"maxBsonObjectSize" : 16777216,
"localTime" : ISODate("2012-10-30T19:39:26.352Z"),
"ok" : 1
}
[v2.2.0@special199b:50002 (db:mdm) rs_1347997619:7=ARBITER]>
Nik Kolev
Oct 30, 2012, 4:39:48 PM10/30/12
to mongodb...@googlegroups.com
Oh. Read some code. Found my issue.
I am instantiating+initializing the MongoServerSettings that I pass to MongoServer.Create like that:
var settings = new MongoServerSettings
{
DefaultCredentials = creds,
ReadPreference = ReadPreference.PrimaryPreferred,
Servers = servers,
SafeMode = SafeMode.True
};
Well, the MongoServerSettings default ctor says:
public MongoServerSettings()
{
_connectionMode = ConnectionMode.Direct;
...
}
Argh...Seems to me that the default connection mode probably should to be Automatic. Oh, it is automatic at HEAD, but not at the 1.6.0.x and 1.6.1.y tags.
craiggwilson
Oct 30, 2012, 4:45:16 PM10/30/12
to mongodb...@googlegroups.com
Yep... Good catch. We actually noticed that as well recently (which is why it was changed in head). Funny that you are the first person indicating an issue... Most people use the connection string I guess.
Well, sorry 'bout the confusion. It'll be fixed in 1.7 which will be coming out in the near future.
Nik Kolev
Oct 30, 2012, 5:38:04 PM10/30/12
to mongodb...@googlegroups.com
sounds good. perhaps you guys would put a jira in against 1.6 to make it easier for people getting burned by this issue to find the workaround. i watched the 1.6 webinar - http://www.10gen.com/events/webinar/dot-net-driver-update - which on slide 46 or so states that Automatic is now the default connection mode, which is why i didn't bother with explicitly specifying it when initializing the MongoServerSettings.
Reply all
Reply to author
Forward
0 new messages