Date: Tue, 30 Oct 2012 12:11:37 -0700 (PDT)
From: Nik Kolev <nko...@gmail.com>
To: mongodb-csharp@googlegroups.com
Message-Id: <b6f69bfa-3f0a-441d-b710-22cc203f2992@googlegroups.com>
In-Reply-To: <edcd4105-3039-4b20-9303-6b7b359086df@googlegroups.com>
References: <7c6fd0e0-1700-44ec-865b-72cff5a8da61@googlegroups.com>
 <CAJCJWG0AFeVOfcgtCSz6ubFrYWbuup_CCz4TURi=fi01cC6Cuw@mail.gmail.com>
 <edcd4105-3039-4b20-9303-6b7b359086df@googlegroups.com>
Subject: Re: [mongodb-csharp] ReplicaSet configuration for reads/writes
MIME-Version: 1.0
Content-Type: multipart/mixed; 
	boundary="----=_Part_1719_7112102.1351624297483"

------=_Part_1719_7112102.1351624297483
Content-Type: multipart/alternative; 
	boundary="----=_Part_1720_12215787.1351624297483"

------=_Part_1720_12215787.1351624297483
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 7bit

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.

On Friday, October 26, 2012 2:39:37 PM UTC-4, Nik Kolev wrote:
>
> 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.
>
> On Friday, October 26, 2012 10:09:58 AM UTC-4, Robert Stam wrote:
>>
>> 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.
>>
>> On Thu, Oct 25, 2012 at 5:39 PM, Nik Kolev <nko...@gmail.com> wrote:
>>
>>> 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
>>>
>>>
>>>
>>>
>>
------=_Part_1720_12215787.1351624297483
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable

<div>OK. Couldn't get to it on Monday - it was Sandy times. Anyways after s=
ome breakpointing and messing with the status of the nodes in my replca set=
 I am pretty sure I know what's going on.</div><div>- To recap my env, I ha=
ve 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.</div><div>- The problem occurs with the=
 same underlying reason regardless of whether the ReadPreference is Primary=
 or PrimaryPreferred.</div><div>- The problem occurs when the first instanc=
e 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.</div><div>- In both readPreference cases, the Ins=
tances array of the MongoServer object contained just one MongoServerInstan=
ce which was pointing to the secondary mongod. The InstanceType was Replica=
SetMember. The ReplicaSetInformation was correctly identifying the replica =
set name, how many members there were in the replica set, and what the prim=
ary member was. I can post a screenshot of the state I am describing here l=
ater today (as certain things are blocked at w$rk).</div><div><br></div><di=
v>Unfortunately things did not get better with the 1.6.1 version of the dri=
ver. The same issue exists there.</div><br>On Friday, October 26, 2012 2:39=
:37 PM UTC-4, Nik Kolev wrote:<blockquote class=3D"gmail_quote" style=3D"ma=
rgin: 0;margin-left: 0.8ex;border-left: 1px #ccc solid;padding-left: 1ex;">=
Thanks Robert. I'll try to get to this in the next couple of hours. If I do=
n't I'll send update with my findings on Monday.<br><br>On Friday, October =
26, 2012 10:09:58 AM UTC-4, Robert Stam wrote:<blockquote class=3D"gmail_qu=
ote" style=3D"margin:0;margin-left:0.8ex;border-left:1px #ccc solid;padding=
-left:1ex">In 1.6 it was possible for ReadPreference.<wbr>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 re=
sult.<div>
<br></div><div>The second result is harder to explain. It looks like you ar=
e connecting directly to a secondary, because the ReadPreference appears to=
 be ignored, which only happens when connecting directly to a server.</div>
<div><br></div><div>Can you make sure you are actually connecting to the re=
plica set in replica set mode? One way you could do that is to put a breakp=
oint on your call that is throwing the exception and checking the MongoServ=
er.Instances property and reporting back how many entries the Instances arr=
ay has and what the InstanceType is for each instance.</div>
<div><br></div><div>You could also check your MongoCursor.ReadPreference ju=
st before executing the query to verify that the cursor has the ReadPrefere=
nce you wanted. In order to examine the cursor you might have to introduce =
an intermediate variable.</div>
<div><br></div><div>Let me know what you find and we can proceed from there=
.<br><br><div class=3D"gmail_quote">On Thu, Oct 25, 2012 at 5:39 PM, Nik Ko=
lev <span dir=3D"ltr">&lt;<a>nko...@gmail.com</a>&gt;</span> wrote:<br>
<blockquote class=3D"gmail_quote" style=3D"margin:0 0 0 .8ex;border-left:1p=
x #ccc solid;padding-left:1ex">Environment:<div>- host: Windows 7<br><div>-=
 mongod: v2.2 (mongodb-win32-x86_64-<wbr>2008plus-2.2.0)</div><div>- mongo =
setup: 3 mongod processes running on the same host in a replica set, 2 real=
 and 1 arbiter</div>
<div>- csharp driver: v.1.6.0.4624</div></div><div><br></div><div>I create =
a MongoServer by providing a MongoServerSetings with the following properti=
es:</div><div>- SafeMode =3D SafeMode.True</div><div>- Servers =3D a collec=
ttion of all 3 mongods' MongoServerAddress-es</div>
<div>- ReadPreference =3D PrimaryPrefered</div><div><br></div><div>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 wr=
ite. 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):</div>
<div>=3D=3D=3D</div><div>{"responseStatus":{"errorCode"<wbr>:"MongoSafeMode=
Exception","<wbr>message":"Safemode detected an error 'not master'. (Respon=
se 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}]MongoD=
B.Driver.<wbr>MongoSafeModeException: Safemode detected an error 'not maste=
r'. (Response was { \"err\" : \"not master\", \"code\" : 10056, \"n\" : 0, =
\"lastOp\" : { \"$timestamp\" : NumberLong(0) }, \"connectionId\" : 1569, \=
"ok\" : 1.0 }).\r\n &nbsp; at MongoDB.Driver.Internal.<wbr>MongoConnection.=
SendMessage(<wbr>MongoRequestMessage message, SafeMode safeMode, String dat=
abaseName) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Driver\\Internal\\=
<wbr>MongoConnection.cs:line 549\r\n &nbsp; at MongoDB.Driver.<wbr>MongoCol=
lection.Remove(<wbr>IMongoQuery query, RemoveFlags flags, SafeMode safeMode=
) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Driver\\Core\\<wbr>MongoCol=
lection.cs:line 1312\r\n &nbsp; at MongoDB.Driver.<wbr>MongoCollection.Remo=
ve(<wbr>IMongoQuery query) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Dr=
iver\\Core\\<wbr>MongoCollection.cs:line 1272<br>
</div><div>=3D=3D=3D</div><div><br></div><div>What's&nbsp;</div><div><br></=
div><div>Guessing here the collection when initially obtained was backed by=
 a connection to the slave replica and that's why the read succeeded but th=
e write did not. If that's the case how would one use the driver for such s=
cenarios?</div>
<div><br></div><div>Moreover, going with my guess I changed the read prefer=
ence to Primary (just Primary). Then even more weirdness happened. I got an=
 exception even before the write was attempted, but when the function was t=
rying to do the read:</div>
<div>=3D=3D=3D</div><div>{"responseStatus":{"errorCode"<wbr>:"MongoQueryExc=
eption","<wbr>message":"QueryFailure flag was not master and slaveOk=3Dfals=
e (response was { \"$err\" : \"not master and slaveOk=3Dfalse\", \"code\" :=
 13435 }).","stackTrace":"[ById: 10/25/2012 9:05:30 PM]:\n[REQUEST: {id:1}]=
MongoDB.Driver.<wbr>MongoQueryException: QueryFailure flag was not master a=
nd slaveOk=3Dfalse (response was { \"$err\" : \"not master and slaveOk=3Dfa=
lse\", \"code\" : 13435 }).\r\n &nbsp; at MongoDB.Driver.Internal.<wbr>Mong=
oReplyMessage`1.ReadFrom(<wbr>BsonBuffer buffer, IBsonSerializationOptions =
serializationOptions) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Driver\=
\Internal\\<wbr>MongoReplyMessage.cs:line 99\r\n &nbsp; at MongoDB.Driver.I=
nternal.<wbr>MongoConnection.<wbr>ReceiveMessage[TDocument](<wbr>BsonBinary=
ReaderSettings readerSettings, IBsonSerializationOptions serializationOptio=
ns) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Driver\\Internal\\<wbr>Mo=
ngoConnection.cs:line 475\r\n &nbsp; at MongoDB.Driver.<wbr>MongoCursorEnum=
erator`1.<wbr>GetReply(MongoConnection connection, MongoRequestMessage mess=
age) in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\Driver\\Core\\<wbr>Mongo=
CursorEnumerator.cs:line 296\r\n &nbsp; at MongoDB.Driver.<wbr>MongoCursorE=
numerator`1.<wbr>GetFirst() in C:\\work\\rstam\\mongo-csharp-<wbr>driver\\D=
river\\Core\\<wbr>MongoCursorEnumerator.cs:line 253\r\n &nbsp; at MongoDB.D=
river.<wbr>MongoCursorEnumerator`1.<wbr>MoveNext() in C:\\work\\rstam\\mong=
o-csharp-<wbr>driver\\Driver\\Core\\<wbr>MongoCursorEnumerator.cs:line 141<=
br>
</div><div>=3D=3D=3D</div><div><br></div><div>I see the error in the mongod=
's log (this is the SECONDARY mongod's log):</div><div><div>=3D=3D=3D</div>=
<div>Thu Oct 25 22:05:30 [conn1665] assertion 13435 not master and slaveOk=
=3Dfalse ns:mdm.policies query:{ ids: "1" }</div>
<div>Thu Oct 25 22:05:30 [conn1665] problem detected during query over mdm.=
policies : { $err: "not master and slaveOk=3Dfalse", code: 13435 }</div></d=
iv><div>=3D=3D=3D</div><div>FWIW I don't see the first error I discussed ca=
ptured in one shape or another in the mongod's logs - I checked in the logs=
 for all 3 of my mongod processes.</div>
<div><br></div><div>I assumed that setting the ReadPreference to Primary wo=
uld let the driver know that all connections need to be asked of the primar=
y mongod. I guess that's not what happened here for me?</div><div><br>
</div><div>Ideas/Suggestions/Recs would be greatly appreciated.</div><div><=
br></div><div>Thanks, -nik</div><div><br></div><div><br></div><div><br></di=
v></blockquote></div><br></div>
</blockquote></blockquote>
------=_Part_1720_12215787.1351624297483--

------=_Part_1719_7112102.1351624297483--