15

I have a Mongo replica set with a few secondaries. A box, which hosts a secondary instance, crashed and lost the database.

I started the secondary Mongo instance again and now it's stuck in STARTUP2 for more than 12 hours. Does it make sense ? The docs say Mongo should be in STARTUP2 for a short period of time before entering the RECOVERING state

What does STARTUP2 exactly mean ? Is it copying the database from the primary ? How can I verify it (assuming the Mongo is running in Linux) ?

6 Answers 6

14

The answer of eoinbrazil is partly incorrect. A new Node can be in STARTUP2 for a long time. The link the posted says:

Each member of a replica set enters the STARTUP2 state as soon as mongod finishes loading that member’s configuration, at which time it becomes an active member of the replica set. The member then decides whether or not to undertake an initial sync. If a member begins an initial sync, the member remains in STARTUP2 until all data is copied and all indexes are built. Afterwards, the member transitions to RECOVERING.

I'm administering a 700 GB collection and, when I add a new node the STARTUP2 state remains well over 24 hours. But you can still see if there is something happening, by watching if the database grows. You can see the size of the database on the new node with

show databases

or you can also observe the data directory, to see if it is still growing. (on linux with the commands ls, df, du, iotop, etc ....)

3
  • 2
    show databases fails with not master and slaveOk=false
    – JDPeckham
    Dec 12, 2019 at 16:19
  • 1
    By looking at the logs you can see the progress. For example it will show something like: [rsSync] Index Build: 2538000/22982417 11% Jan 24, 2020 at 14:36
  • Thanks for sharing! I ran into this as well with a similarly sized dataset (on Atlas, so I can't even see the progress afaik). It would be good to get an answer from someone at MongoDB. 24h+ to start a new replica is not very practical
    – framp
    Jan 21, 2021 at 20:53
4

The STARTUP2 state means "The member has joined the set and is running an initial sync. Eligible to vote." A member of a RS enters this state once the MongoD process completes loading it's configuration. In this state, the member has created threads to handle the internal replication operations but it has yet to change state to Recovering and onwards from that to Secondary (see the [state and their details in the docs]).

If your node has been in this state for more than a brief period then you are encountering some strange behaviour. This is pretty much impossible to analyse without the logs to determine why it is stuck. Running rs.status() and db.printSlaveReplicationInfo() will give you some details on the local picture on the node.

The normal approach to resolve this would be to shutdown the node, wipe its data files (those files in the dbpath), and restart it. This will restart the initial sync process and it should move to SECONDARY. If it gets stuck in STARTUP2 again, you'll need to look at the logs to gather more information as to why - there are a range of causes but one that can happen is a flaky network or some local resource contention.

One point to note is that whilst an initial sync is underway the node will remain in STARTUP2 so depending on the amount of data being synced this could be a considerable amount of time (potentially days).

2
  • Thanks. Now it looks ok, the node in SECONDARY state. We use MongoDB 2.4.6, by the way. I still do not understand why the node was in STARTUP2 so much time, though.
    – Michael
    Feb 16, 2014 at 13:24
  • It is really hard to tell without logs what was happening, there's a whole host of reasons from flaky local network to just a very slow sync to hardware / os settings on your node. It really is a piece of string question without more info but I'm glad it is resolved and back online.
    – eoinbrazil
    Feb 17, 2014 at 0:00
2

The easiest way to figure out what is going on in your scenario is to tail the server log on what is going on with the following command:

# This will filter all noise out and leave you only with the "replication" information
tail /var/log/mongodb/mongod.log -f -n 100000 | grep repl

The above command will output what is going on with the synchronisation process.

In case there is nothing there, then use the following:

# This will filter out all "ACCESS" entries and you will be able to more easily dig out what the problem is.
tail /var/log/mongodb/mongod.log -f -n 10000 | grep -v ACCESS

P. S. A member in STARTUP2 state can actually vote (according to docs).

2

Answer for MongoDB 5.0 release.

The initial sync may take some time - be patient. As far as I see it runs in two steps. First MongoDB clones all collections, i.e. it makes a "plain" copy of all collections. You can monitor this by connecting to syncing member and run rs.status().initialSyncStatus.databases

shard_03:STARTUP2> rs.status().initialSyncStatus.databases    
{
        "failedInitialSyncAttempts" : 0,
        "maxFailedInitialSyncAttempts" : 10,
        "initialSyncStart" : ISODate("2022-04-28T08:33:36.519Z"),
        "totalInitialSyncElapsedMillis" : 6548240,
        "initialSyncAttempts" : [ ],
        "approxTotalDataSize" : NumberLong("488957278026"),
        "approxTotalBytesCopied" : NumberLong("519033102224"),
        "remainingInitialSyncEstimatedMillis" : -379443,
        "appliedOps" : 0,
        "initialSyncOplogStart" : Timestamp(1651134817, 16004),
        "totalTimeUnreachableMillis" : NumberLong(0),
        "databases" : {
                "databasesToClone" : 2,
                "databasesCloned" : 5,
...
                "plau01mipmed0" : {
                        "collections" : 9,
                        "clonedCollections" : 8,
                        "start" : ISODate("2022-04-28T09:56:10.907Z"),
                        "plau01mipmed0.sessions" : {
                                "documentsToCopy" : 16449103,
                                "documentsCopied" : 16891103,
                                "indexes" : 4,
                                "fetchedBatches" : 242,
                                "bytesToCopy" : NumberLong("3816816827"),
                                "approxBytesCopied" : NumberLong("3918735896"),
                                "start" : ISODate("2022-04-28T09:56:10.907Z"),
                                "end" : ISODate("2022-04-28T09:59:02.068Z"),
                                "elapsedMillis" : 171161,
                                "receivedBatches" : 242
                        },
                        "plau01mipmed0.ignored" : {
                                "documentsToCopy" : 8095615,
                                "documentsCopied" : 5711111,
                                "indexes" : 2,
                                "fetchedBatches" : 86,
                                "bytesToCopy" : 1966181814,
                                "approxBytesCopied" : 1382088862,
                                "start" : ISODate("2022-04-28T10:22:17.332Z"),
                                "receivedBatches" : 86
                        }

After some time you should get result like

shard_03:STARTUP2> rs.status().initialSyncStatus.databases    
...
{ 
  ... 
  "databases" : { 
    "databasesToClone" : 0, 
    "databasesCloned" : 7
    }
}

After that MongoDB starts to apply the oplog. You can monitor it with this command:

shard_03:STARTUP2> rs.status().members.filter(x => x.name == db.hello().me).forEach(
   x => printjson(
      {
         date: ISODate(),
         name: x.name,
         stateStr: x.stateStr,
         optimeDate: x.optimeDate,
         oplog_BacklogSeconds: (ISODate() - x.optimeDate) / 1000
      }
   )
)

{
   "date" : ISODate("2022-04-28T11:27:42.111Z"),
   "name" : "d-mipmdb-sh2-03:27018",
   "stateStr" : "STARTUP2",
   "optimeDate" : ISODate("2022-04-28T09:40:50Z"),
   "oplog_BacklogSeconds" : 6412.111
}

Again, you need to be patient. oplog_BacklogSeconds should slowly decrease. Sooner or later, the member state should go to SECONDARY. As this time the sync is not fully done, i.e. oplog_BacklogSeconds may still show a high number, but it should decrease rather fast. When it becomes 1-2 Seconds then it is fully done.

1

One possible cause is that your secondary become "stale" as stated here .

When you are resyncing a member, make sure the RS is not under heavy load.

1

STARTUP2 state could be due to not enough disc space. Well, since there is no where to sync, it can only stay @ STARTUP2 state.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.