Re: Replication test

From: Adnan Khurram <adnankhurram@xxxxxxxxx>
To: mongodb-user <mongodb-user@xxxxxxxxxxxxxxxx>
Date: Thu, 5 May 2016 09:10:40 -0700 (PDT)
Why ads?
Hi Jeff,
Here is the log from the beginning of the program in java.

May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Cluster created with settings {hosts=[akhurraml2:27017, 
akhurraml2:27018, akhurraml2:27019], mode=MULTIPLE, 
requiredClusterType=UNKNOWN, serverSelectionTimeout='30000 ms', 
maxWaitQueueSize=500}
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server akhurraml2:27017 to client view of cluster
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server akhurraml2:27018 to client view of cluster
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Adding discovered server akhurraml2:27019 to client view of cluster
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by WritableServerSelector from cluster description 
ClusterDescription{type=UNKNOWN, connectionMode=MULTIPLE, 
all=[ServerDescription{address=akhurraml2:27017, type=UNKNOWN, 
state=CONNECTING}, ServerDescription{address=akhurraml2:27018, 
type=UNKNOWN, state=CONNECTING}, 
ServerDescription{address=akhurraml2:27019, type=UNKNOWN, 
state=CONNECTING}]}. Waiting for 30000 ms before timing out
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:3, serverValue:7}] to 
akhurraml2:27019
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27019, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1192559, setName='m101', 
canonicalAddress=AKhurramL2:27019, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27017', tagSet=TagSet{[]}, electionId=null, 
setVersion=3}
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Discovered cluster type of REPLICA_SET
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:2, serverValue:9}] to 
akhurraml2:27017
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27017, type=REPLICA_SET_PRIMARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1141655, setName='m101', 
canonicalAddress=AKhurramL2:27017, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27017', tagSet=TagSet{[]}, 
electionId=572b58430000000000000001, setVersion=3}
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Setting max election id to 572b58430000000000000001 from replica set 
primary akhurraml2:27017
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Setting max set version to 3 from replica set primary akhurraml2:27017
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Discovered replica set primary akhurraml2:27017
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:4, serverValue:10}] to 
akhurraml2:27017
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:1, serverValue:9}] to 
akhurraml2:27018
May 05, 2016 5:03:58 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27018, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=825965, setName='m101', 
canonicalAddress=AKhurramL2:27018, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27017', tagSet=TagSet{[]}, electionId=null, 
setVersion=3}



and this is the log from when the first primary does rs.stepDown()

May 05, 2016 5:07:59 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:5, serverValue:17}] to 
akhurraml2:27017
May 05, 2016 5:07:59 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27017, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1832142, setName='m101', 
canonicalAddress=AKhurramL2:27017, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}
May 05, 2016 5:07:59 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: No server chosen by WritableServerSelector from cluster description 
ClusterDescription{type=REPLICA_SET, connectionMode=MULTIPLE, 
all=[ServerDescription{address=akhurraml2:27017, 
type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, 
version=ServerVersion{versionList=[3, 2, 0]}, minWireVersion=0, 
maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=1832142, 
setName='m101', canonicalAddress=AKhurramL2:27017, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}, 
ServerDescription{address=akhurraml2:27018, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1369341, setName='m101', 
canonicalAddress=AKhurramL2:27018, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27017', tagSet=TagSet{[]}, electionId=null, 
setVersion=3}, ServerDescription{address=akhurraml2:27019, 
type=REPLICA_SET_SECONDARY, state=CONNECTED, ok=true, 
version=ServerVersion{versionList=[3, 2, 0]}, minWireVersion=0, 
maxWireVersion=4, maxDocumentSize=16777216, roundTripTimeNanos=1086987, 
setName='m101', canonicalAddress=AKhurramL2:27019, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27017', tagSet=TagSet{[]}, electionId=null, 
setVersion=3}]}. Waiting for 30000 ms before timing out
May 05, 2016 5:08:02 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27019, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1547645, setName='m101', 
canonicalAddress=AKhurramL2:27019, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}
May 05, 2016 5:08:03 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27018, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1224290, setName='m101', 
canonicalAddress=AKhurramL2:27018, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='null', tagSet=TagSet{[]}, electionId=null, setVersion=3}
May 05, 2016 5:08:09 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27018, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1126162, setName='m101', 
canonicalAddress=AKhurramL2:27018, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27018', tagSet=TagSet{[]}, 
electionId=572b6fe80000000000000002, setVersion=3}
May 05, 2016 5:08:09 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27017, type=REPLICA_SET_SECONDARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1218621, setName='m101', 
canonicalAddress=AKhurramL2:27017, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27018', tagSet=TagSet{[]}, electionId=null, 
setVersion=3}
May 05, 2016 5:08:10 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Monitor thread successfully connected to server with description 
ServerDescription{address=akhurraml2:27018, type=REPLICA_SET_PRIMARY, 
state=CONNECTED, ok=true, version=ServerVersion{versionList=[3, 2, 0]}, 
minWireVersion=0, maxWireVersion=4, maxDocumentSize=16777216, 
roundTripTimeNanos=1055612, setName='m101', 
canonicalAddress=AKhurramL2:27018, hosts=[AKhurramL2:27017, 
AKhurramL2:27018, AKhurramL2:27019], passives=[], arbiters=[], 
primary='AKhurramL2:27018', tagSet=TagSet{[]}, 
electionId=572b6fe80000000000000002, setVersion=3}
May 05, 2016 5:08:10 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Setting max election id to 572b6fe80000000000000002 from replica set 
primary akhurraml2:27018
May 05, 2016 5:08:10 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Discovered replica set primary akhurraml2:27018
May 05, 2016 5:08:10 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Opened connection [connectionId{localValue:6, serverValue:10}] to 
akhurraml2:27018

and here is what i get if i do rs.stepDown() on the new primary now.

May 05, 2016 5:09:35 PM com.mongodb.diagnostics.logging.JULLogger log
WARNING: Got socket exception on connection [connectionId{localValue:6, 
serverValue:10}] to akhurraml2:27018. All connections to akhurraml2:27018 
will be closed.
May 05, 2016 5:09:35 PM com.mongodb.diagnostics.logging.JULLogger log
INFO: Closed connection [connectionId{localValue:6, serverValue:10}] to 
akhurraml2:27018 because there was a socket exception raised by this 
connection.
Exception in thread "main" com.mongodb.MongoSocketReadException: Exception 
receiving message
at 
com.mongodb.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:480)
at 
com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:225)
at 
com.mongodb.connection.UsageTrackingInternalConnection.receiveMessage(UsageTrackingInternalConnection.java:102)
at 
com.mongodb.connection.DefaultConnectionPool$PooledConnection.receiveMessage(DefaultConnectionPool.java:435)
at 
com.mongodb.connection.WriteCommandProtocol.receiveMessage(WriteCommandProtocol.java:234)
at 
com.mongodb.connection.WriteCommandProtocol.execute(WriteCommandProtocol.java:104)
at 
com.mongodb.connection.InsertCommandProtocol.execute(InsertCommandProtocol.java:67)
at 
com.mongodb.connection.InsertCommandProtocol.execute(InsertCommandProtocol.java:37)
at 
com.mongodb.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:159)
at 
com.mongodb.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:286)
at 
com.mongodb.connection.DefaultServerConnection.insertCommand(DefaultServerConnection.java:115)
at 
com.mongodb.operation.MixedBulkWriteOperation$Run$2.executeWriteCommandProtocol(MixedBulkWriteOperation.java:455)
at 
com.mongodb.operation.MixedBulkWriteOperation$Run$RunExecutor.execute(MixedBulkWriteOperation.java:646)
at 
com.mongodb.operation.MixedBulkWriteOperation$Run.execute(MixedBulkWriteOperation.java:401)
at 
com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:179)
at 
com.mongodb.operation.MixedBulkWriteOperation$1.call(MixedBulkWriteOperation.java:168)
at 
com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:230)
at 
com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:221)
at 
com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:168)
at 
com.mongodb.operation.MixedBulkWriteOperation.execute(MixedBulkWriteOperation.java:74)
at com.mongodb.Mongo.execute(Mongo.java:781)
at com.mongodb.Mongo$2.execute(Mongo.java:764)
at 
com.mongodb.MongoCollectionImpl.executeSingleWriteRequest(MongoCollectionImpl.java:515)
at com.mongodb.MongoCollectionImpl.insertOne(MongoCollectionImpl.java:306)
at com.mongodb.MongoCollectionImpl.insertOne(MongoCollectionImpl.java:297)
at com.nextcontrols.App.main(App.java:33)
Caused by: java.net.SocketException: Software caused connection abort: recv 
failed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mongodb.connection.SocketStream.read(SocketStream.java:85)
at 
com.mongodb.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:491)
at 
com.mongodb.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:221)
... 24 more





On Thursday, 5 May 2016 15:24:58 UTC+1, Jeff Yemin wrote:

Hi Adnan,

Please provide the stack trace of the exception so it's clear which 
exception the driver is throwing.


Regards,
Jeff

On Thu, May 5, 2016 at 6:18 AM, Adnan Khurram <adnank...@xxxxxxxxx 
<javascript:>> wrote:

HI Guys,
I am exploring the replication functionality in MongoDB, just wanted to 
clarify a scenario.

I have a java program which is inserting values in the db constantly in a 
three instance replica set, now if i do rs.stepDown() on the primary the 
java program waits for a couple of seconds for the elections and then 
continues inserting but if i know do the rs.stepDown() on the new primary, 
my program just throws and exception and exits.

For the first primary it works after the election by itself whereas in 
case of the second primary stepping down it throws and exception. Could 
someone please explain why is it doing that whereas i thought it would 
continue even in case of the second step down.

Kind Regards,


-- 
You received this message because you are subscribed to the Google Groups 
"mongodb-user"
group.
 
For other MongoDB technical support options, see: 
https://docs.mongodb.org/manual/support/
--- 
You received this message because you are subscribed to the Google Groups 
"mongodb-user" group.
To unsubscribe from this group and stop receiving emails from it, send an 
email to mongodb-user...@xxxxxxxxxxxxxxxx <javascript:>.
To post to this group, send email to mongod...@xxxxxxxxxxxxxxxx 
<javascript:>.
Visit this group at https://groups.google.com/group/mongodb-user.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/mongodb-user/c2aa38bb-eee2-4946-89e6-d34b7508fb43%40googlegroups.com ;
<https://groups.google.com/d/msgid/mongodb-user/c2aa38bb-eee2-4946-89e6-d34b7508fb43%40googlegroups.com?utm_medium=email&utm_source=footer>
.
For more options, visit https://groups.google.com/d/optout.




-- 
You received this message because you are subscribed to the Google Groups "mongodb-user"
group.

For other MongoDB technical support options, see: https://docs.mongodb.org/manual/support/
--- 
You received this message because you are subscribed to the Google Groups "mongodb-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mongodb-user+unsubscribe@xxxxxxxxxxxxxxxx.
To post to this group, send email to mongodb-user@xxxxxxxxxxxxxxxx.
Visit this group at https://groups.google.com/group/mongodb-user.
To view this discussion on the web visit https://groups.google.com/d/msgid/mongodb-user/50ca4e02-800c-4f44-bb5b-7dd36cba4a70%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Why ads?