[SERVER-3025] Cannot start new replica set member if another member recovering Created: 30/Apr/11  Updated: 29/May/12  Resolved: 20/Jan/12

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 1.8.1
Fix Version/s: None

Type: Bug Priority: Critical - P2
Reporter: David Mytton Assignee: Kristina Chodorow (Inactive)
Resolution: Incomplete Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Sat Apr 30 00:53:23 [initandlisten] MongoDB starting : pid=23198 port=27018 dbpath=/mongodbdata/ 64-bit
Sat Apr 30 00:53:23 [initandlisten] db version v1.8.1, pdfile version 4.5
Sat Apr 30 00:53:23 [initandlisten] git version: a429cd4f535b2499cc4130b06ff7c26f41c00f04
Sat Apr 30 00:53:23 [initandlisten] build sys info: Linux bs-linux64.10gen.cc 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41

Example log from primary:

Sat Apr 30 00:53:23 [initandlisten] MongoDB starting : pid=23198 port=27018 dbpath=/mongodbdata/ 64-bit
Sat Apr 30 00:53:23 [initandlisten] db version v1.8.1, pdfile version 4.5
Sat Apr 30 00:53:23 [initandlisten] git version: a429cd4f535b2499cc4130b06ff7c26f41c00f04
Sat Apr 30 00:53:23 [initandlisten] build sys info: Linux bs-linux64.10gen.cc 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Sat Apr 30 00:53:23 [initandlisten] journal dir=/mongodbdata/journal
Sat Apr 30 00:53:23 [initandlisten] recover : no journal files present, no recovery needed
Sat Apr 30 00:53:23 [initandlisten] waiting for connections on port 27018
Sat Apr 30 00:53:23 [websvr] web admin interface listening on port 28018
Sat Apr 30 00:53:23 [startReplSets] trying to contact rs2b:27018
Sat Apr 30 00:54:23 [dur] lsn set 59524
Sat Apr 30 00:55:23 [dur] lsn set 119356
Sat Apr 30 00:55:33 [startReplSets] DBClientCursor::init call() failed
Sat Apr 30 00:55:33 [startReplSets] trying to contact rs2d:27018
Sat Apr 30 00:55:33 [startReplSets] replSet STARTUP2
Sat Apr 30 00:55:33 [replica set sync] replSet SECONDARY
Sat Apr 30 00:55:33 [rs Manager] replSet can't see a majority, will not try to elect self
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet info rs2d:27018 is up
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet member rs2d:27018 SECONDARY
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet info rs2b:27018 is down (or slow to respond): socket exception
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet info rs2arbiter:27018 is up
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet member rs2arbiter:27018 ARBITER
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet info rs2c:27018 is up
Sat Apr 30 00:55:33 [ReplSetHealthPollTask] replSet member rs2c:27018 SECONDARY
Sat Apr 30 00:55:34 [rs Manager] replSet info electSelf 0
Sat Apr 30 00:55:34 [rs Manager] replSet PRIMARY
Sat Apr 30 00:55:34 [conn80] request split points lookup for chunk sd.metrics_110430 { : 4235, : 1 } -->> { : 4672, : 1 }
Sat Apr 30 00:55:34 [conn80] request split points lookup for chunk sd.metrics_110430 { : 2282, : 3 } -->> { : 2916, : 1 }
Sat Apr 30 00:55:34 [conn80] max number of requested split points reached (2) before the end of chunk sd.metrics_110430 { : 2282, : 3 } -->> { : 2916, : 1 }
Sat Apr 30 00:55:34 [conn80] updated set (set1) to: set1/rs1a:27018,rs1b:27018
Sat Apr 30 00:55:34 [ReplicaSetMonitorWatcher] starting

Example log from secondary:

Sat Apr 30 00:52:48 [FileAllocator] allocating new datafile /mongodbdata/sd.14, filling with zeroes...
Sat Apr 30 00:52:49 [replica set sync] done building bottom layer, going to commit
Sat Apr 30 00:52:50 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:52:52 [replica set sync] done for 943965 records 14.183secs
Sat Apr 30 00:52:52 [replica set sync] info: indexing in foreground on this replica; was a background index build on the primary
Sat Apr 30 00:52:52 [replica set sync] building new index on

{ p: 1 }

for sd.metrics_110427
Sat Apr 30 00:52:55 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 413ms
Sat Apr 30 00:52:55 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:52:58 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 1189ms
Sat Apr 30 00:52:59 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 141ms
Sat Apr 30 00:53:00 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
55800/13337875 0%
Sat Apr 30 00:53:03 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 1441ms
Sat Apr 30 00:53:04 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 355ms
Sat Apr 30 00:53:05 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:05 [conn2332] query admin.$cmd ntoreturn:1 command:

{ replSetGetStatus: 1 }

reslen:944 392ms
Sat Apr 30 00:53:06 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 943ms
Sat Apr 30 00:53:06 [conn2326] query admin.$cmd ntoreturn:1 command:

{ ismaster: 1 }

reslen:204 122ms
Sat Apr 30 00:53:07 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 131ms
Sat Apr 30 00:53:10 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:11 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 319ms
179200/13337875 1%
Sat Apr 30 00:53:15 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:16 [ReplSetHealthPollTask] DBClientCursor::init call() failed
Sat Apr 30 00:53:19 [FileAllocator] done allocating datafile /mongodbdata/sd.14, size: 2047MB, took 30.554 secs
Sat Apr 30 00:53:20 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:20 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 106ms
820100/13337875 6%
Sat Apr 30 00:53:25 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:30 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
2000000/13337875 14%
Sat Apr 30 00:53:35 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:40 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:40 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 137ms
Sat Apr 30 00:53:44 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 199ms
3036500/13337875 22%
Sat Apr 30 00:53:45 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:50 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
4058800/13337875 30%
Sat Apr 30 00:53:55 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:53:55 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 159ms
Sat Apr 30 00:53:56 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 210ms
Sat Apr 30 00:53:57 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 188ms
Sat Apr 30 00:54:00 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
5070800/13337875 38%
Sat Apr 30 00:54:05 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:07 [conn2361] query admin.$cmd ntoreturn:1 command:

{ serverStatus: 1 }

reslen:1309 122ms
Sat Apr 30 00:54:10 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
6181700/13337875 46%
Sat Apr 30 00:54:15 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:20 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
7409500/13337875 55%
Sat Apr 30 00:54:25 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:28 got kill or ctrl c or hup signal 15 (Terminated), will terminate after current cmd ends
Sat Apr 30 00:54:30 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
8786500/13337875 65%
Sat Apr 30 00:54:35 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:40 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:45 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
10000000/13337875 74%
Sat Apr 30 00:54:50 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
11000000/13337875 82%
Sat Apr 30 00:54:55 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:54:58 [conn5] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88ada9b0fbd0e3f85be10') }

reslen:60 300066ms
Sat Apr 30 00:54:58 [conn6] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88c0b34414290739c4361') }

reslen:60 300038ms
Sat Apr 30 00:54:59 [conn8] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4dba81bae94dca76f44b4da9') }

reslen:60 300038ms
Sat Apr 30 00:54:59 [conn10] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88b6432edb36beaf641dc') }

reslen:60 300037ms
Sat Apr 30 00:54:59 [conn12] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4dac476ca0afad8f0fc8f264') }

reslen:60 300038ms
Sat Apr 30 00:54:59 [conn11] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88b3b1b313c594100f4a0') }

reslen:60 300038ms
Sat Apr 30 00:54:59 [conn13] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88b0e4c1b3ceddf4d98c2') }

reslen:60 300037ms
Sat Apr 30 00:55:00 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:55:00 [conn15] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4db946634a51cc51d0c0fdae') }

reslen:60 300037ms
Sat Apr 30 00:55:01 [conn9] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4dac6dfb64b672b58b4dd341') }

reslen:60 300037ms
Sat Apr 30 00:55:01 [conn19] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4dac69d23cb1fbe556fc9649') }

reslen:60 300038ms
Sat Apr 30 00:55:01 [conn17] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88a950ac28b5f7b9319a8') }

reslen:60 300037ms
Sat Apr 30 00:55:02 [conn21] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4dac57ff537bc0a5071744b9') }

reslen:60 300038ms
Sat Apr 30 00:55:02 [conn18] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88b610923140971e45e9c') }

reslen:60 300038ms
Sat Apr 30 00:55:02 [conn20] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88bb7a111a56ab1e9577a') }

reslen:60 300038ms
12164100/13337875 91%
Sat Apr 30 00:55:05 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:55:10 [conn22] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4db9913caec9018878b1cbf9') }

reslen:60 300038ms
Sat Apr 30 00:55:10 [conn16] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4da88c1e1f70448ebeb3c4c2') }

reslen:60 300038ms
Sat Apr 30 00:55:10 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
13308100/13337875 99%
Sat Apr 30 00:55:15 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:55:16 [replica set sync] external sort used : 14 files in 143 secs
Sat Apr 30 00:55:20 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
Sat Apr 30 00:55:25 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time
3639700/13337875 27%
Sat Apr 30 00:55:30 [rs Manager] replSet info not trying to elect self, do not yet have a complete set of data from any point in time


Operating System: Linux
Participants:

 Description   

1) Set up a replica set with 3 members (primary, secondary and arbiter)
2) Kill the secondary, delete the data and restart it so it starts a resync. Let it get to the stage where it's building indexes
3) Kill the primary and restart it. It tries to contact the secondary but hangs. It waits for a response which it never gets. It doesn't time out.

I have to kill -9 the the secondary in order to get the primary to start up. Regular kill doesn't work because it's completing the index building.



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

I am tentatively closing, feel free to comment if this is still an issue for anyone in 2.0.

Comment by Kristina Chodorow (Inactive) [ 30/Nov/11 ]

There were some issues with 1.8 getting into an infinite loop recv() (instead of timing out). Has anyone had this happen with 2.0 as well? The looping bug should be fixed, at least.

I've been unable to reproduce so far, I'll look at the code and see if there's anywhere we're not setting a timeout.

Comment by Everett Li [ 22/Sep/11 ]

When two slaves are added (rs.add) to a replica at same time, there are posibilities that one slave can't start replication. It can be solved by restarting the slave.

Thu Sep 22 04:55:24 [startReplSets] trying to contact node1
Thu Sep 22 04:55:27 [initandlisten] connection accepted from 10.245.12.37:43728 #22
Thu Sep 22 04:55:37 [startReplSets] DBClientCursor::init call() failed
Thu Sep 22 04:55:37 [startReplSets] replSet error loading configurations 10276 DBClientBase::findOne: transport error: node2 query:

{ authenticate: 1, nonce: "d3f2dda7659b198d", user: "__system", key: "3d634236be2250990221425890795a46" }

Thu Sep 22 04:55:37 [startReplSets] replSet error replication will not start
Thu Sep 22 04:55:37 [startReplSets] replSet error loading set config
Thu Sep 22 04:55:37 [startReplSets] replSet error fatal, stopping replication
Thu Sep 22 04:55:37 [startReplSets] replSet ~RSBase called
Thu Sep 22 04:55:37 [startReplSets] replSet caught exception in startReplSets thread: DBClientBase::findOne: transport error: node2 query:

{ authen ticate: 1, nonce: "d3f2dda7659b198d", user: "__system", key: "3d634236be2250990221425890795a46" }
Comment by Edward M. Goldberg [ 12/Jul/11 ]

I have the same line in my failing Secondary server:

Tue Jul 12 02:46:09 [initandlisten] recover done
Tue Jul 12 02:46:13 [dur] lsn set 0
Tue Jul 12 02:46:14 [initandlisten] query local.system.namespaces reslen:36 nscanned:5

{ name: /^local.temp./ }

nreturned:0 463ms
Tue Jul 12 02:46:18 [initandlisten] waiting for connections on port 27017
Tue Jul 12 02:46:18 [websvr] web admin interface listening on port 28017
Tue Jul 12 02:46:22 [conn8] query admin.$cmd ntoreturn:1 command:

{ ismaster: 1 }

reslen:176 286ms
Tue Jul 12 02:46:24 [conn10] query admin.$cmd ntoreturn:1 command:

{ ismaster: 1 }

reslen:176 1919ms
Tue Jul 12 02:46:27 [conn11] query admin.$cmd ntoreturn:1 command:

{ ismaster: 1 }

reslen:176 2291ms
Tue Jul 12 02:46:28 [startReplSets] DBClientCursor::init call() failed
Tue Jul 12 02:46:30 [conn16] query admin.$cmd ntoreturn:1 command:

{ ismaster: 1 }

reslen:176 2511ms

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