Replication set got re-intialized after boot

[Ganesh]

Guys,

Wanted your thoughts / opinion on what might have happened in my local replication cluster.

BACKGROUND:

Am running my mongo cluster [Current Stable Release (3.2.6)] on CentOS 6 VM. The application was writing/reading to/from the mongo cluster, with replication happening almost always immediately. Haven't changed anything different from the default configuration that default mongo replication configuration provides. It's a 2 node cluster (n0 PRIMARY & n1 SECONDARY) & data/reads/writes is insignificant. As its my local cluster, am the only user / client. In other words, the application was able to read / write seamlessly & all read / writes were happening through PRIMARY node, with data being replicated without any issues.

The cluster is been running for couple of weeks & haven't seen any issue but for today morning. Having said that, something changed, noticed the replication is NO longer happening, & the reason being the replicaSetId no longer match. The logs had  

"New and old configurations differ in replica set ID; old was 572945ca042e24d5daeaaecf, and new is 572c026a4739cf7c1f78992d"

Here is the command that I use to start the mongo daemon in replication mode

start mongo in replication mode 

mongod --dbpath /usr/local/data --replSet xxx-cluster --fork --logpath /var/log/cluster.log

Question is, how did the replicaSetId change, I thought, the ID is set during rs.initiate() & trying to run initiate() again does not  succeed. However in my case, looks like initiate did happen AGAIN (on a cluster where the replication was already running). The mongodb instance was restarted on one particular node (n0) & it's in that node the initiate happened (please see the log excerpt from below). 

Here's is what I see in the mongo db log except from today (13th May)

2016-05-13T10:37:32.700-0400 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "xxx-cluster", version: 101930, protocolVersion: 1, members: [ { _id: 0, host: "n0:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('572945ca042e24d5daeaaecf') } }

The following log statements is from the other node (n1), when originally n1 & n0 were added (which was on 9th May) to the same replication cluster. Notice the replicaSetId then, which is still the same on node n1 (that no longer matches with n0), which is why the heartbeat failed & replication stopped.

2016-05-09T22:51:51.919-0400 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker

2016-05-09T22:51:51.921-0400 I NETWORK  [initandlisten] waiting for connections on port 27017

2016-05-09T22:51:51.927-0400 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "xxx-cluster", version: 2, protocolVersion: 1, members: [ { _id: 0, host: "n0:27017", arbiterOn

ly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "n1:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0,

 tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErr

orDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('572c026a4739cf7c1f78992d') } }

2016-05-09T22:51:51.927-0400 I REPL     [ReplicationExecutor] This node is n1:27017 in the config

2016-05-09T22:51:51.927-0400 I REPL     [ReplicationExecutor] transition to STARTUP2

2016-05-09T22:51:51.927-0400 I REPL     [ReplicationExecutor] Starting replication applier threads

2016-05-09T22:51:51.928-0400 I REPL     [ReplicationExecutor] transition to RECOVERING

2016-05-09T22:51:51.935-0400 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to n0:27017

2016-05-09T22:51:51.937-0400 I REPL     [ReplicationExecutor] Member n0:27017 is now in state SECONDARY

2016-05-09T22:51:51.937-0400 I REPL     [ReplicationExecutor] transition to SECONDARY

2016-05-09T22:51:52.040-0400 I NETWORK  [initandlisten] connection accepted from 192.168.90.10:46654 #1 (1 connection now open)

2016-05-09T22:51:53.968-0400 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:45105 #2 (2 connections now open)

2016-05-09T22:51:56.939-0400 I REPL     [ReplicationExecutor] Member n0:27017 is now in state PRIMARY

2016-05-09T22:51:56.967-0400 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:45106 #3 (3 connections now open)

2016-05-09T22:51:57.937-0400 I REPL     [ReplicationExecutor] syncing from: n0:27017

2016-05-09T22:51:57.943-0400 I REPL     [SyncSourceFeedback] setting syncSourceFeedback to n0:27017

2016-05-09T22:51:57.949-0400 I ASIO     [NetworkInterfaceASIO-BGSync-0] Successfully connected to n0:27017

After 10:37 AM today, had to physically drop the local db in both node & re-instate replication as new to get to the state as before. Basically start the instance in non replication mode, drop the local db & then start in replication mode, initiate & add nodes to the cluster.

QUESTIONS:

1. Why did n0 initialize the replication set (on 13th May when it was already part of the replication that was running from 9th May)? I thought its only by rs.initiate() one can initiatialize mongo replication set (May be am missing something here).  More over in a cluster where replication is initialized, trying to run rs.initialize(), always failed with error "already initialized". How did n0 succeed (on May 13th, when it was rebooted) & what triggered the initialize operation. I just tried to shutdown the instance & start it all over again using the start mongo in replication mode  command as above & noticed the log excerpt from above. 
   
2. How to recover from a situation like this if it happens, I had to drop the local db by running mongo in normal mode (a.k.a Standalone mode) & then start mongo db in replication mode & run rs.initiate() & add n1 to the replication via rs.add() as I  did before, trying to set up new replication set configuration.
   

Thanks,

Ganesh

[Asya Kamsky]

Just to clarify - you did not execute any other replica set configuration commands?

So when the n0 host went down, n1 stayed as secondary and you had no PRIMARY until you reconfigured the replica set after discovering this configuration issue on n0?

Also, is this the only replica set you have running?

Asya

--
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...@googlegroups.com.
To post to this group, send email to mongod...@googlegroups.com.
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/673c6046-a436-496e-979b-00215521ce20%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Asya Kamsky
Lead Product Manager
MongoDB
Download MongoDB - mongodb.org/downloads
Free MongoDB Monitoring - cloud.mongodb.com
Free Online Education - university.mongodb.com
Get Involved - mongodb.org/community
We're Hiring! - https://www.mongodb.com/careers

[Ganesh]

That's correct Asya.

No replica set commands were executed. The secondary node n1 kept trying to reach n0, until today morning before I rebooted node n0. You are right, no write / read operations went through until I reconfigured.

Yep this is the only replica set running. 

Thanks,

Ganesh

On Friday, May 13, 2016 at 8:38:39 PM UTC-4, Asya Kamsky wrote:

Just to clarify - you did not execute any other replica set configuration commands?

So when the n0 host went down, n1 stayed as secondary and you had no PRIMARY until you reconfigured the replica set after discovering this configuration issue on n0?

Also, is this the only replica set you have running?

Asya

[Asya Kamsky]

Ganesh,

In scenarios like these it's helpful to have all the logs to analyze - both from n0 before and after you rebooted/restarted, and from n1 during the entire time (or at least times overlapping the n0 logs).

I see the suspect statement from May 13th from n0 but it would be more enlightening to see all of the log from startup until that statement, as well as the same time period from n1.

The thing is that between May 9th and May 13th, there *was* a replica set reconfiguration done, because the config is different on the 9th and on the 13th (I'm going to reformat these to show configs):

2016-05-13T10:37:32.700-0400 I REPL     [ReplicationExecutor] 

New replica set config in use: 

{

   _id: "xxx-cluster",

   version: 101930,

   protocolVersion: 1,

   members: [

       { _id: 0,

         host: "n0:27017",

         arbiterOnly: false,

         buildIndexes: true,

         hidden: false,

         priority: 1.0,

         tags: {},

         slaveDelay: 0,

         votes: 1

       }

   ],

   settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('572945ca042e24d5daeaaecf') } 

}

2016-05-09T22:51:51.927-0400 I REPL     [ReplicationExecutor] 

New replica set config in use: 

{

   _id: "xxx-cluster",

   version: 2,

   protocolVersion: 1,

   members: [

       { _id: 0,

         host: "n0:27017",

         arbiterOnly: false,

         buildIndexes: true,

         hidden: false,

         priority: 1.0,

         tags: {},

         slaveDelay: 0,

         votes: 1

       }, {

         _id: 1,

         host: "n1:27017",

         arbiterOnly: false,

         buildIndexes: true,

         hidden: false,

         priority: 1.0,

         tags: {},

         slaveDelay: 0,

         votes: 1 

        } 

   ],

   settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('572c026a4739cf7c1f78992d') } 

}

Here's an observation for you: neither of these replica sets were created on May 9th or May 13th.   

One of them was created on May 4th around 8:45pm, the other on May 6th around 10:33pm.  

When you create (initiate) a replica set, the replica set ID is generated and since it's an ObjectId we can decode its first four bytes into ISODate in mongo shell:  

> ObjectId("572945ca042e24d5daeaaecf").getTimestamp()

ISODate("2016-05-04T00:43:54Z")

> ObjectId("572c026a4739cf7c1f78992d").getTimestamp()

ISODate("2016-05-06T02:33:14Z")

This is why I asked if the two are the only members and if there is another replica set (maybe of the same name).   There is definitely something going on that's not exactly what you described.  For example, when I run rs.initiate, what I see in the logs is:

2016-04-20T15:00:16.822-0500 I COMMAND  [conn1] initiate : no configuration specified. Using a default configuration for the set

2016-04-20T15:00:16.822-0500 I COMMAND  [conn1] created this configuration for initiation : { _id: "mixed", version: 1, members: [ { _id: 0, host: "xxx2:27017" } ] }

2016-04-20T15:00:16.822-0500 I REPL     [conn1] replSetInitiate admin command received from client

2016-04-20T15:00:16.822-0500 I REPL     [conn1] replSetInitiate config object with 1 members parses ok

2016-04-20T15:00:16.823-0500 I REPL     [conn1] ******

2016-04-20T15:00:16.823-0500 I REPL     [conn1] creating replication oplog of size: 500MB...

2016-04-20T15:00:16.826-0500 I STORAGE  [conn1] Starting WiredTigerRecordStoreThread local.oplog.rs

2016-04-20T15:00:16.826-0500 I STORAGE  [conn1] The size storer reports that the oplog contains 0 records totaling to 0 bytes

2016-04-20T15:00:16.826-0500 I STORAGE  [conn1] Scanning the oplog to determine where to place markers for truncation

2016-04-20T15:00:16.836-0500 I REPL     [conn1] ******

2016-04-20T15:00:16.843-0500 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "mixed", version: 1, protocolVersion: 1, members: [ { _id: 0, host: "xxx2:27017", arbiterOnly: false, buildIndexes: true, hidden

: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults

: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('5717dfd0787dd73e49345cc6') } }

2016-04-20T15:00:16.843-0500 I REPL     [ReplicationExecutor] This node is xxx2:27017 in the config

2016-04-20T15:00:16.843-0500 I REPL     [ReplicationExecutor] transition to STARTUP2

2016-04-20T15:00:16.843-0500 I REPL     [conn1] Starting replication applier threads

2016-04-20T15:00:16.843-0500 I REPL     [ReplicationExecutor] transition to RECOVERING

2016-04-20T15:00:16.845-0500 I REPL     [ReplicationExecutor] transition to SECONDARY

The config ObjectId decodes to exact time it was generated:

> ObjectId('5717dfd0787dd73e49345cc6').getTimestamp()

ISODate("2016-04-20T20:00:16Z")

Note that this does not match your logs from May 9th at all, instead it appears on May 9th according to your logs, it got its logs from its own local database.      I would check all your logs, look for places where the server started up and look for something like this in the logs - it will indicate where and when the actual rs.initiate commands were run:

I REPL     [initandlisten] Did not find local voted for document at startup;  NoMatchingDocument: Did not find replica set lastVote document in local.replset.election

I REPL     [initandlisten] Did not find local replica set configuration document at startup;  NoMatchingDocument: Did not find replica set configuration document in local.system.replset

All replication related log lines will have REPL in them, so that's the place to start looking.

Good luck,

Asya "just call me Sherlock" Kamsky

To view this discussion on the web visit https://groups.google.com/d/msgid/mongodb-user/6d0b504d-cbfb-42b1-a53c-307d57bd2daa%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Ganesh]

Thank you Asya, that is helpful.

I think you are right, I have multiple clusters running in various "isolated" (at least that's what I thought originally) networks, however the replication set names are SAME. After you shared the details, the replicaSetId deciphered time-stamp does point to the situation when the cluster in context was not even created. Looks like the isolated clusters are not REALLY isolated & were able to see each other, resulting in situation what I saw.

Decided to name the replication clusters dynamically that way even if they see each other, we do not fall into this trap.

Glad to know, the replicaSetId are ONLY created during INITIATE.

Once again thanks for your valuable pointers & help.

Cheers,

Ganesh