Is Progress Being Made In ROLLBACK?

[Stuart Rench]

I have a replicaset member that went into rollback mode this morning.  It is producing a massive amount of log entries similar to:

Sun Apr 28 15:53:56 [rsSync] replSet WARNING ignoring op on rollback no _id TODO : inv.system.indexes { ts: Timestamp 1367150501000|31, h: -3893062772133308244, op: "i", ns: "inv.system.indexes", o: { unique: true, ns: "inv.fs.configs.chunks", name: "files_id_1_n_1", key: { files_id: 1, n: 1 } } }

 Are these expected?  How can I tell if it is making forward progress, or if I will need to blow away the data directory and start a fresh sync?

Thanks!

[Stuart Rench]

Additionally, I have found a series of logs similar to:

Sun Apr 28 16:49:08 [rsSync] replSet rollback error RS101 reached beginning of local oplog

Sun Apr 28 16:49:08 [rsSync] replSet   them:      [name of primary]:27017 scanned: 40993835

Sun Apr 28 16:49:08 [rsSync] replSet   theirTime: Jul 16 09:03:02 5003d8c6:13

Sun Apr 28 16:49:08 [rsSync] replSet   ourTime:   Apr 19 00:01:27 51708957:17

Sun Apr 28 16:49:08 [rsSync] replSet rollback 2 error RS101 reached beginning of local oplog [2]

Sun Apr 28 16:50:04 [rsSync] replSet syncing to: [name of primary]:27017

Sun Apr 28 16:50:05 [rsSync] replSet our last op time written: Apr 28 12:01:41:1f

Sun Apr 28 16:50:05 [rsSync] replset source's GTE: Apr 28 13:01:00:20

Sun Apr 28 16:50:05 [rsSync] replSet rollback 0

Sun Apr 28 16:50:05 [rsSync] replSet rollback 1

Sun Apr 28 16:50:05 [rsSync] replSet rollback 2 FindCommonPoint

Sun Apr 28 16:50:05 [rsSync] replSet info rollback our last optime:   Apr 28 12:01:41:1f

Sun Apr 28 16:50:05 [rsSync] replSet info rollback their last optime: Apr 28 16:50:05:6

Sun Apr 28 16:50:05 [rsSync] replSet info rollback diff in end of log times: -17304 seconds

It seems like something I should be concerned about.  Is it?

Any Ideas where "theirTime" is coming from?  Not sure why it thinks it is July.  I checked the system date on both other replicaset members and everyone is NTP synced.

[Asya Kamsky]

What version of mongoDB are you running?

[Stuart Rench]

2.0.9

--
--
You received this message because you are subscribed to the Google
Groups "mongodb-user" group.
To post to this group, send email to mongod...@googlegroups.com
To unsubscribe from this group, send email to
mongodb-user...@googlegroups.com
See also the IRC channel -- freenode.net#mongodb
 
---
You received this message because you are subscribed to a topic in the Google Groups "mongodb-user" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/mongodb-user/TuF44RF66xo/unsubscribe?hl=en.
To unsubscribe from this group and all its topics, send an email to mongodb-user...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Asya Kamsky]

The July timestamp is a bit puzzling - can you provide more information about your replica set (and anything of interest that happened in the last failover of the primary)?   For starters rs.status() from the current primary and the node in question may be informative.

Asya

[Stuart Rench]

I am fairly confident that a switchover hasn't happened in quite some time (I will have to work through this massive log to get a definitive answer).

We do a daily snapshot of a secondary that has us doing a balancer pause, then a fsynclock on the node, followed by the backup.  It appears that the problem occured at the end of that backup when we issued the fsyncunlock request. (it was locked for less than 3 hours).

From the problem member:

ROLLBACK> rs.status()

{

        "set" : "rs_shard1",

        "date" : ISODate("2013-04-28T19:41:33Z"),

        "myState" : 9,

        "syncingTo" : "proddb1c.remainder_of_address:27017",

        "members" : [

                {

                        "_id" : 0,

                        "name" : "proddb1a.remainder_of_address:27017",

                        "health" : 1,

                        "state" : 9,

                        "stateStr" : "ROLLBACK",

                        "optime" : {

                                "t" : 1367150501000,

                                "i" : 31

                        },

                        "optimeDate" : ISODate("2013-04-28T12:01:41Z"),

                        "self" : true

                },

                {

                        "_id" : 1,

                        "name" : "proddb1b.remainder_of_address:27017",

                        "health" : 1,

                        "state" : 1,

                        "stateStr" : "PRIMARY",

                        "uptime" : 1946196,

                        "optime" : {

                                "t" : 1367178092000,

                                "i" : 61

                        },

                        "optimeDate" : ISODate("2013-04-28T19:41:32Z"),

                        "lastHeartbeat" : ISODate("2013-04-28T19:41:33Z"),

                        "pingMs" : 1

                },

                {

                        "_id" : 2,

                        "name" : "proddb1c.remainder_of_address:27017",

                        "health" : 1,

                        "state" : 2,

                        "stateStr" : "SECONDARY",

                        "uptime" : 1946196,

                        "optime" : {

                                "t" : 1367178092000,

                                "i" : 30

                        },

                        "optimeDate" : ISODate("2013-04-28T19:41:32Z"),

                        "lastHeartbeat" : ISODate("2013-04-28T19:41:32Z"),

                        "pingMs" : 0

                }

        ],

        "ok" : 1

}

From the current primary:

PRIMARY> rs.status()

{

"set" : "rs_shard1",

"date" : ISODate("2013-04-28T19:42:49Z"),

"myState" : 1,

"syncingTo" : "proddb1c.remainder_of_address:27017",

"members" : [

{

"_id" : 0,

"name" : "proddb1a.remainder_of_address:27017",

"health" : 1,

"state" : 9,

"stateStr" : "ROLLBACK",

"uptime" : 1946284,

"optime" : {

"t" : 1367150501000,

"i" : 31

},

"optimeDate" : ISODate("2013-04-28T12:01:41Z"),

"lastHeartbeat" : ISODate("2013-04-28T19:42:47Z"),

"pingMs" : 3,

"errmsg" : "rollback 2 FindCommonPoint"

},

{

"_id" : 1,

"name" : "proddb1b.remainder_of_address:27017",

"health" : 1,

"state" : 1,

"stateStr" : "PRIMARY",

"optime" : {

"t" : 1367178169000,

"i" : 8

},

"optimeDate" : ISODate("2013-04-28T19:42:49Z"),

"self" : true

},

{

"_id" : 2,

"name" : "proddb1c.remainder_of_address:27017",

"health" : 1,

"state" : 2,

"stateStr" : "SECONDARY",

"uptime" : 1949313,

"optime" : {

"t" : 1367178167000,

"i" : 17

},

"optimeDate" : ISODate("2013-04-28T19:42:47Z"),

"lastHeartbeat" : ISODate("2013-04-28T19:42:47Z"),

"pingMs" : 0

}

],

"ok" : 1

}

[Stuart Rench]

So far I haven't attempted to restart mongo or anything manually, I have just been letting it do its thing.  Is there anything that you suggest that I try in the short term?

[Stuart Rench]

I tried to restart mongo and the saga continues.  It appears to always have the same pattern of throwing the rollback error, spitting out lots of warnings, and then eventually throwing the rollback error again.

We have been considering an upgrade to 2.2 for quite some time.  Do you think there will be any benefit in trying that?  Or should I simple rebuild the member?

Is there any other information that should be pulled before I do this?

[Asya Kamsky]

It would be nice to understand what triggered this before upgrading or completely repopulating - I'm not aware of scenarios where a secondary has to rollback since it's not accepting any writes that don't exist on the primary.   One question I do have is how big is the oplog on the primary and problem child?  Can you do db.printReplicationInfo() on both?

Simplest way to "reboot" this member would be to restore a snapshot of the other secondary on it and let it catch up from there but I would hesitate to suggest that since you ran into trouble when doing a snapshot.

Here are a couple of questions:  do you use journaling?  (It's the default) if yes then why do fsyncLock() for the snapshot?  Is the journal on a different physical drive than the data files?  (that would be another reason).

It would be nice to see the part of the log when fsyncUnlock was issued to see what happened next that ended up in this state, but I can understand if it's too complex to sanitize the logs for public viewing.  You can open a support case in the SUPPORT project - it's for private community cases and allows you to upload your logs where only 10gen engineers can see them...

Asya

[Stuart Rench]

Asya,

I sent you the details that you asked for.  And in the meantime, I have attempted a restore from the snapshot.  The same issue occured.

Is there anything else to try before deleting the data directory?

/Stuart

[Adam C]

Another nice thing to know - can you confirm that your hosts are in sync in terms of time?  Do you run ntpd?

5003d8c6 translates to 1342429382 which is: Mon, 16 Jul 2012 09:03:02

Hence the "their time" is July *last year*.  Therefore the secondary thinks it is ~9 months ahead of the node that is now primary and tries to do a roll back.

Another clue might come from your rs.status() output - did you modify it at all manually, or do both actually say this?

"syncingTo" : "proddb1c.remainder_of_address:27017",

If so, then that proddb1c host would be the main suspect for me - if you block that host (temporarily) using iptables and retry the restore from snapshot, does it succeed (that's the only way to guarantee that proddb1a will attempt to sync from the primary instead of proddb1c)?

Adam

[Stuart Rench]

I checked all of the hosts at the time I noticed those time stamps.  The OS's all were synced with NTP and were correct.

/Stuart