[SERVER-4810] If a replica set member with higher priority comes online, current primary relinquishes primary state Created: 30/Jan/12  Updated: 11/Jul/16  Resolved: 29/Mar/12

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 2.0.2
Fix Version/s: 2.0.5, 2.1.1

Type: Bug Priority: Major - P3
Reporter: David Mytton Assignee: Kristina Chodorow (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 10.04 LTS x64
Mac OS X 10.7


Issue Links:
Depends
Operating System: ALL
Participants:

 Description   

If a replica set member with higher priority comes online, the current primary relinquishes primary state regardless of the state of the other member and before that member has any status. This means a functioning cluster will lose state and require an election just because another member came online with a higher priority. This does not happen if there is no priority set for any member.

1. Set up a replica set with 3 nodes, 2 of them with high priorities:

{
 "_id" : "test1",
 "members" : [
 {
 "_id" : 0,
 "host" : "localhost:27017",
 "priority" : 3
 },
 {
 "_id" : 1,
 "host" : "localhost:27018",
 "priority" : 2
 },
 {
 "_id" : 2,
 "host" : "localhost:27019"
 },
 ]
}

2. Wait for the set to come online with "localhost:27017" as the primary
3. On "localhost:27017" issue rs.stepDown() so that "localhost:27018" becomes primary
4. Kill mongod on "localhost:27017"
5. Delete the data directory on "localhost:27017" so that when it comes up it is not immediately ready to take over as primary and requires a resync.
5. Restart mongod on "localhost:27017"

What happens: "localhost:27018" immediately loses its primary state then gets reelected as primary
What should happen: "localhost:27018" should remain primary until it is safe to re-elect "localhost:27017" as the higher priority node

Log from "localhost:27018"

Mon Jan 30 15:50:17 [rsHealthPoll] DBClientCursor::init call() failed
Mon Jan 30 15:50:17 [rsHealthPoll] replSet info localhost:27017 is down (or slow to respond): DBClientBase::findN: transport error: localhost:27017 query: { replSetHeartbeat: "test1", v: 1, pv: 1, checkEmpty: false, from: "localhost:27018" }
Mon Jan 30 15:50:17 [rsHealthPoll] replSet member localhost:27017 is now in state DOWN
Mon Jan 30 15:50:33 [rsHealthPoll] replSet member localhost:27017 is up
Mon Jan 30 15:50:33 [rsMgr] stepping down localhost:27018
Mon Jan 30 15:50:33 [rsMgr] replSet relinquishing primary state
Mon Jan 30 15:50:33 [rsMgr] replSet SECONDARY
Mon Jan 30 15:50:33 [rsMgr] replSet closing client sockets after reqlinquishing primary
Mon Jan 30 15:50:33 [conn1] end connection 127.0.0.1:57612
Mon Jan 30 15:50:33 [rsHealthPoll] replSet info localhost:27019 is down (or slow to respond): socket exception
Mon Jan 30 15:50:33 [rsHealthPoll] replSet member localhost:27019 is now in state DOWN
Mon Jan 30 15:50:33 [rsMgr] replSet not electing self, not all members up and we have been up less than 5 minutes
Mon Jan 30 15:50:35 [conn12] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:57654] 
Mon Jan 30 15:50:35 [rsHealthPoll] replSet member localhost:27019 is up
Mon Jan 30 15:50:35 [rsHealthPoll] replSet member localhost:27019 is now in state SECONDARY
Mon Jan 30 15:50:35 [rsMgr] not electing self, localhost:27019 would veto
Mon Jan 30 15:50:37 [rsMgr] not electing self, localhost:27019 would veto
Mon Jan 30 15:50:40 [conn10] end connection 127.0.0.1:57650
Mon Jan 30 15:50:40 [initandlisten] connection accepted from 127.0.0.1:57680 #13
Mon Jan 30 15:50:41 [rsMgr] not electing self, localhost:27019 would veto
Mon Jan 30 15:50:43 [initandlisten] connection accepted from 127.0.0.1:57683 #14
Mon Jan 30 15:50:46 [rsHealthPoll] replSet member localhost:27017 is now in state STARTUP2
Mon Jan 30 15:50:46 [rsMgr] not electing self, localhost:27017 would veto
Mon Jan 30 15:50:46 [rsMgr] not electing self, localhost:27017 would veto
Mon Jan 30 15:50:52 [rsMgr] replSet info electSelf 1
Mon Jan 30 15:50:52 [rsMgr] replSet PRIMARY
Mon Jan 30 15:50:54 [rsHealthPoll] replSet member localhost:27017 is now in state RECOVERING
Mon Jan 30 15:50:54 [initandlisten] connection accepted from 127.0.0.1:57687 #15
Mon Jan 30 15:50:59 [conn14] end connection 127.0.0.1:57683



 Comments   
Comment by auto [ 20/Apr/12 ]

Author:

{u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}

Message: Better log message SERVER-4810
Branch: v2.0
https://github.com/mongodb/mongo/commit/672793ce4f079ee259f149a7b530e42dd09cca0c

Comment by auto [ 20/Apr/12 ]

Author:

{u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}

Message: Check optimes before stepping down due to priority SERVER-4810
Branch: v2.0
https://github.com/mongodb/mongo/commit/49144209b1c537692945594d909713a2fc669db0

Comment by auto [ 13/Feb/12 ]

Author:

{u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}

Message: Better log message SERVER-4810
Branch: master
https://github.com/mongodb/mongo/commit/7226ed15e92150301663220455b613705d64dc6d

Comment by auto [ 13/Feb/12 ]

Author:

{u'login': u'kchodorow', u'name': u'Kristina', u'email': u'kristina@10gen.com'}

Message: Check optimes before stepping down due to priority SERVER-4810
Branch: master
https://github.com/mongodb/mongo/commit/4402792701d5df7b9669c2894e10d2c7dc035c58

Comment by Kristina Chodorow (Inactive) [ 30/Jan/12 ]

Thanks for the logs! I see what's going wrong, should be easy to fix.

Comment by David Mytton [ 30/Jan/12 ]

Matching log from "localhost:27017"

Mon Jan 30 15:50:16 [conn16] end connection 127.0.0.1:57655
Mon Jan 30 15:50:16 [conn15] end connection 127.0.0.1:57651
Mon Jan 30 15:50:16 [conn14] end connection 127.0.0.1:57645
Mon Jan 30 15:50:16 [rsSync] Socket recv() errno:9 Bad file descriptor 127.0.0.1:27018
Mon Jan 30 15:50:16 [rsSync] SocketException: remote: 127.0.0.1:27018 error: 9001 socket exception [1] server [127.0.0.1:27018] 
Mon Jan 30 15:50:16 [rsSync] replSet syncThread: 10278 dbclient error communicating with server: localhost:27018
Mon Jan 30 15:50:16 [interruptThread] shutdown: closing all files...
Mon Jan 30 15:50:16 [interruptThread] closeAllFiles() finished
Mon Jan 30 15:50:16 [interruptThread] journalCleanup...
Mon Jan 30 15:50:16 [interruptThread] removeJournalFiles
Mon Jan 30 15:50:16 [interruptThread] shutdown: removing fs lock...
Mon Jan 30 15:50:16 dbexit: really exiting now
Mon Jan 30 15:50:33 [initandlisten] MongoDB starting : pid=36974 port=27017 dbpath=/Users/david/test1/ 64-bit host=Shibuya.local
Mon Jan 30 15:50:33 [initandlisten] db version v2.0.2, pdfile version 4.5
Mon Jan 30 15:50:33 [initandlisten] git version: 514b122d308928517f5841888ceaa4246a7f18e3
Mon Jan 30 15:50:33 [initandlisten] build info: Darwin erh2.10gen.cc 9.6.0 Darwin Kernel Version 9.6.0: Mon Nov 24 17:37:00 PST 2008; root:xnu-1228.9.59~1/RELEASE_I386 i386 BOOST_LIB_VERSION=1_40
Mon Jan 30 15:50:33 [initandlisten] options: { dbpath: "/Users/david/test1/", port: 27017, replSet: "test1" }
Mon Jan 30 15:50:33 [initandlisten] journal dir=/Users/david/test1/journal
Mon Jan 30 15:50:33 [initandlisten] recover : no journal files present, no recovery needed
Mon Jan 30 15:50:33 [websvr] admin web console waiting for connections on port 28017
Mon Jan 30 15:50:33 [rsStart] couldn't connect to localhost:27017: couldn't connect to server localhost:27017
Mon Jan 30 15:50:33 [initandlisten] waiting for connections on port 27017
Mon Jan 30 15:50:33 [initandlisten] connection accepted from 127.0.0.1:57674 #1
Mon Jan 30 15:50:33 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Mon Jan 30 15:50:33 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done
Mon Jan 30 15:50:33 [initandlisten] connection accepted from 127.0.0.1:57675 #2
Mon Jan 30 15:50:33 [conn2] end connection 127.0.0.1:57675
Mon Jan 30 15:50:34 [initandlisten] connection accepted from 127.0.0.1:57677 #3
Mon Jan 30 15:50:35 [initandlisten] connection accepted from 127.0.0.1:57678 #4
Mon Jan 30 15:50:40 [initandlisten] connection accepted from 127.0.0.1:57681 #5
Mon Jan 30 15:50:40 [conn3] end connection 127.0.0.1:57677
Mon Jan 30 15:50:43 [rsStart] trying to contact localhost:27018
Mon Jan 30 15:50:43 [rsStart] trying to contact localhost:27019
Mon Jan 30 15:50:43 [rsStart] replSet got config version 1 from a remote, saving locally
Mon Jan 30 15:50:43 [rsStart] replSet info saving a newer config version to local.system.replset
Mon Jan 30 15:50:43 [FileAllocator] allocating new datafile /Users/david/test1/local.ns, filling with zeroes...
Mon Jan 30 15:50:43 [FileAllocator] creating directory /Users/david/test1/_tmp
Mon Jan 30 15:50:43 [FileAllocator] done allocating datafile /Users/david/test1/local.ns, size: 16MB,  took 0.32 secs
Mon Jan 30 15:50:43 [FileAllocator] allocating new datafile /Users/david/test1/local.0, filling with zeroes...
Mon Jan 30 15:50:44 [FileAllocator] done allocating datafile /Users/david/test1/local.0, size: 64MB,  took 0.503 secs
Mon Jan 30 15:50:44 [FileAllocator] allocating new datafile /Users/david/test1/local.1, filling with zeroes...
Mon Jan 30 15:50:44 [rsStart] replSet saveConfigLocally done
Mon Jan 30 15:50:44 [rsStart] replSet STARTUP2
Mon Jan 30 15:50:44 [rsSync] ******
Mon Jan 30 15:50:44 [rsSync] creating replication oplog of size: 183MB...
Mon Jan 30 15:50:45 [FileAllocator] done allocating datafile /Users/david/test1/local.1, size: 128MB,  took 1.049 secs
Mon Jan 30 15:50:45 [FileAllocator] allocating new datafile /Users/david/test1/local.2, filling with zeroes...
Mon Jan 30 15:50:45 [rsHealthPoll] replSet member localhost:27018 is up
Mon Jan 30 15:50:45 [rsHealthPoll] replSet member localhost:27018 is now in state SECONDARY
Mon Jan 30 15:50:45 [rsHealthPoll] replSet member localhost:27019 is up
Mon Jan 30 15:50:45 [rsHealthPoll] replSet member localhost:27019 is now in state SECONDARY
Mon Jan 30 15:50:45 [conn4] end connection 127.0.0.1:57678
Mon Jan 30 15:50:46 [initandlisten] connection accepted from 127.0.0.1:57686 #6
Mon Jan 30 15:50:47 [FileAllocator] done allocating datafile /Users/david/test1/local.2, size: 256MB,  took 2.309 secs
Mon Jan 30 15:50:47 [rsSync] ******
Mon Jan 30 15:50:47 [rsSync] replSet initial sync pending
Mon Jan 30 15:50:47 [rsSync] replSet initial sync need a member to be primary or secondary to do our initial sync
Mon Jan 30 15:50:52 [conn6] replSet RECOVERING
Mon Jan 30 15:50:52 [conn6] replSet info voting yea for localhost:27018 (1)
Mon Jan 30 15:50:53 [rsHealthPoll] replSet member localhost:27018 is now in state PRIMARY

Generated at Thu Feb 08 03:07:03 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.