I have a staging environment with Mongo replica set which I refresh on a regular basis. Refresh is done automatically using a bash script.

Staging replica set consists of 3 members (primary, secondary and arbiter). When we refresh we do several steps:

  1. Fetch latest LVM backup of production
  2. Stop both primary and secondary
  3. Completely wipe out data dir for both of them
  4. Extract LVM backup into primaries data folder (removing lock file and data files of local collection)
  5. Start primary which gets elected with the help of the arbiter
  6. Start secondary which does the initial sync from primary

This approach worked for months but it started to fail recently. The problem is with item nr. 5. When primary starts up it decides that it needs to do the initial sync and refuses to become primary. It stays in STARTUP2 state as it is waiting for some other node that could sync from.

Any suggestions? Is this approach even valid? How could I convince primary to-be to have confidence in it's data?

Log from my PRIMARY below:

2014-05-25T16:12:50.180+0200 [initandlisten] MongoDB starting : pid=4654 port=30001 dbpath=pri 64-bit host=vol
2014-05-25T16:12:50.180+0200 [initandlisten] db version v2.6.1
2014-05-25T16:12:50.180+0200 [initandlisten] git version: 4b95b086d2374bdcfcdf2249272fb552c9c726e8
2014-05-25T16:12:50.180+0200 [initandlisten] build info: Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-05-25T16:12:50.180+0200 [initandlisten] allocator: tcmalloc
2014-05-25T16:12:50.180+0200 [initandlisten] options: { net: { port: 30001 }, replication: { oplogSizeMB: 128, replSet: "CorruptionTest" }, storage: { dbPath: "pri", smallFiles: true } }
2014-05-25T16:12:50.180+0200 [initandlisten] 
2014-05-25T16:12:50.180+0200 [initandlisten] ** WARNING: Readahead for pri is set to 3072KB
2014-05-25T16:12:50.181+0200 [initandlisten] **          We suggest setting it to 256KB (512 sectors) or less
2014-05-25T16:12:50.181+0200 [initandlisten] **          http://dochub.mongodb.org/core/readahead
2014-05-25T16:12:50.279+0200 [initandlisten] journal dir=pri/journal
2014-05-25T16:12:50.279+0200 [initandlisten] recover : no journal files present, no recovery needed
2014-05-25T16:12:50.383+0200 [FileAllocator] allocating new datafile pri/local.ns, filling with zeroes...
2014-05-25T16:12:50.383+0200 [FileAllocator] creating directory pri/_tmp
2014-05-25T16:12:50.414+0200 [FileAllocator] done allocating datafile pri/local.ns, size: 16MB,  took 0.017 secs
2014-05-25T16:12:50.416+0200 [FileAllocator] allocating new datafile pri/local.0, filling with zeroes...
2014-05-25T16:12:50.447+0200 [FileAllocator] done allocating datafile pri/local.0, size: 16MB,  took 0.03 secs
2014-05-25T16:12:50.452+0200 [initandlisten] build index on: local.startup_log properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.startup_log" }
2014-05-25T16:12:50.452+0200 [initandlisten]     added index to empty collection
2014-05-25T16:12:50.452+0200 [initandlisten] waiting for connections on port 30001
2014-05-25T16:12:50.455+0200 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
2014-05-25T16:12:50.455+0200 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done
2014-05-25T16:12:51.455+0200 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
2014-05-25T16:12:51.988+0200 [initandlisten] connection accepted from #1 (1 connection now open)
2014-05-25T16:12:52.456+0200 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
2014-05-25T16:12:52.989+0200 [conn1] end connection (0 connections now open)
2014-05-25T16:12:52.989+0200 [initandlisten] connection accepted from #2 (2 connections now open)
2014-05-25T16:12:53.456+0200 [rsStart] trying to contact vol:30003
2014-05-25T16:12:53.457+0200 [rsStart] replSet I am vol:30001
2014-05-25T16:12:53.457+0200 [rsStart] replSet got config version 2 from a remote, saving locally
2014-05-25T16:12:53.457+0200 [rsStart] replSet info saving a newer config version to local.system.replset: { _id: "CorruptionTest", version: 2, members: [ { _id: 0, host: "vol:30001" }, { _id: 1, host:"vol:30002" }, { _id: 2, host: "vol:30003", arbiterOnly: true } ] }
2014-05-25T16:12:53.458+0200 [rsStart] build index on: local.system.replset properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.system.replset" }
2014-05-25T16:12:53.458+0200 [rsStart]   added index to empty collection
2014-05-25T16:12:53.458+0200 [rsStart] replSet saveConfigLocally done
2014-05-25T16:12:53.461+0200 [rsStart] build index on: local.me properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.me" }
2014-05-25T16:12:53.461+0200 [rsStart]   added index to empty collection
2014-05-25T16:12:53.461+0200 [rsStart] replSet STARTUP2
2014-05-25T16:12:53.461+0200 [rsSync] ******
2014-05-25T16:12:53.461+0200 [rsSync] creating replication oplog of size: 128MB...
2014-05-25T16:12:53.461+0200 [FileAllocator] allocating new datafile pri/local.1, filling with zeroes...
2014-05-25T16:12:53.513+0200 [FileAllocator] done allocating datafile pri/local.1, size: 256MB,  took 0.051 secs
2014-05-25T16:12:53.664+0200 [rsSync] ******
2014-05-25T16:12:53.664+0200 [rsSync] replSet initial sync pending
2014-05-25T16:12:53.664+0200 [rsSync] replSet initial sync need a member to be primary or secondary to do our initial sync
2014-05-25T16:12:55.457+0200 [rsHealthPoll] replSet member vol:30003 is up
2014-05-25T16:12:55.458+0200 [rsHealthPoll] replSet member vol:30003 is now in state ARBITER
  • Please post the actual logs from the primary when it is not elected and stays in STARTUP2 - I suspect either an oplog that is too old, or perhaps missing/broken in some way - the oplog being present and correct is key, but the actual log messages should shine some light on it. If you want to inspect the oplog (run validate etc.) then start the process without --replSet on another port and connect to it as a standalong mongod. – Adam C May 21 '14 at 22:45
  • Log added. If found out that it works as expected if I don't remove local.* files from DB snapshot. This somehow makes sense, but I am still confused. The reason for that is that our scripts that include that delete worked just fine until now. No mongo upgrades happened recently. – slashrsm May 25 '14 at 14:22
  • Couple of initial comments: If this is the log from the primary, then why is it creating files from scratch if you are restoring from a snapshot? The description of what you are doing and the logs don't match up - this looks like a blank node you are starting with just an Arbiter (no data), so where is it supposed to sync from? – Adam C May 25 '14 at 19:03
  • It is primaries log. I assumed it is creating local database which is deleted when we extract snapshot. I assume this was done to remove prod's replicaset configuration (we use slightly different setup on stage). – slashrsm May 25 '14 at 22:28
  • If you remove the local db then you remove the oplog, and with no oplog it will try to sync from scratch. You must include the oplog from the snapshot and not delete it for it to join the set successfully. – Adam C May 25 '14 at 23:55

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.