MongoDB Replica Set SECONDARY Stuck in `ROLLBACK` State

Au cours d'une récente mise à jour automatisée de notre mongodb PRIMARY, lorsque le PRIMARYdémissionnaire est définitivement entré dans un ROLLBACKétat.

Après plusieurs heures dans l' ROLLBACKétat, il n'y avait toujours pas de .bsonfichier de restauration dans le rollbackrépertoire du répertoire de la base de données mongodb. Cela, et aussi cette ligne dans notre fichier journal:, [rsSync] replSet syncThread: 13410 replSet too much data to roll backsemble indiquer que le ROLLBACKprocessus a échoué.

J'aimerais avoir de l'aide pour analyser ce qui s'est exactement passé.

• Il semble que deux annulations différentes se soient produites dans nos journaux. Est-ce le cas ou est-ce que cela a pris 3 heures?
• Si le premier rollback (à 19h00) a réussi, pourquoi rien n'apparaît-il dans notre rollbackrépertoire?
• Une idée de la cause de tous ces avertissements? Cela pourrait-il être lié à l'échec de la restauration?
• Avons-nous perdu 18 secondes de données à cause de la première ROLLBACK?
• Existe-t-il une solution générique au problème "coincé dans l' ROLLBACKétat"? Nous avons fini par devoir arroser l'intégralité de notre base de données et resynchroniser à partir du serveur principal.

Les lignes de journal pertinentes sont:

# Primary coming back after restart...
Tue May 15 19:01:01 [initandlisten] MongoDB starting : pid=3684 port=27017 dbpath=/var/lib/mongodb 64-bit host=magnesium
Tue May 15 19:01:01 [initandlisten] db version v2.0.5, pdfile version 4.5
# ... init stuff
Tue May 15 19:01:01 [initandlisten] journal dir=/var/lib/mongodb/journal
Tue May 15 19:01:01 [initandlisten] recover : no journal files present, no recovery needed
# ... More init stuff
Tue May 15 19:01:03 [rsStart] trying to contact rs1arb1.c9w.co:27017
Tue May 15 19:01:03 [rsStart] trying to contact rs1m2.c9w.co:27017
Tue May 15 19:01:03 [rsStart] replSet STARTUP2
Tue May 15 19:01:03 [rsHealthPoll] replSet member rs1arb1.c9w.co:27017 is up
Tue May 15 19:01:03 [rsHealthPoll] replSet member rs1arb1.c9w.co:27017 is now in state ARBITER
Tue May 15 19:01:03 [rsSync] replSet SECONDARY
Tue May 15 19:01:05 [rsHealthPoll] replSet member rs1m2.c9w.co:27017 is up
Tue May 15 19:01:05 [rsHealthPoll] replSet member rs1m2.c9w.co:27017 is now in state PRIMARY
Tue May 15 19:01:09 [rsSync] replSet syncing to: rs1m2.c9w.co:27017
Tue May 15 19:01:09 [rsSync] replSet our last op time written: May 15 19:00:51:6
Tue May 15 19:01:09 [rsSync] replSet rollback 0
Tue May 15 19:01:09 [rsSync] replSet ROLLBACK
Tue May 15 19:01:09 [rsSync] replSet rollback 1
Tue May 15 19:01:09 [rsSync] replSet rollback 2 FindCommonPoint
Tue May 15 19:01:09 [rsSync] replSet info rollback our last optime:   May 15 19:00:51:6
Tue May 15 19:01:09 [rsSync] replSet info rollback their last optime: May 15 19:01:09:19
Tue May 15 19:01:09 [rsSync] replSet info rollback diff in end of log times: -18 seconds
Tue May 15 19:01:10 [rsSync] replSet WARNING ignoring op on rollback no _id TODO : nimbus.system.indexes { ts: Timestamp 1337108400000|17, h: 1628369028235805797, op: "i", ns: "nimbus.system.indexes", o: { unique: true, name: "pascalquery_ns_key_start_ts_keyvals", key: { __ns__: 1, _key: 1, start_ts: 1, _keyval.a: 1, _keyval.b: 1, _keyval.c: 1, _keyval.d: 1, _keyval.e: 1, _keyval.f: 1, _keyval.g: 1, _keyval.h: 1 }, ns: "nimbus.wifi_daily_series", background: true } }
# ...
# Then for several minutes there are similar warnings
# ...
Tue May 15 19:03:52 [rsSync] replSet WARNING ignoring op on rollback no _id TODO : nimbus.system.indexes { ts: Timestamp 1337097600000|204, h: -3526710968279064473, op: "i", ns: "nimbus.system.indexes", o: { unique: true, name: "pascalquery_ns_key_start_ts_keyvals", key: { __ns__: 1, _key: 1, start_ts: 1, _keyval.a: 1, _keyval.b: 1, _keyval.c: 1, _keyval.d: 1, _keyval.e: 1, _keyval.f: 1, _keyval.g: 1, _keyval.h: 1 }, ns: "nimbus.wifi_daily_series", background: true } }
Tue May 15 19:03:54 [rsSync] replSet rollback found matching events at May 15 15:59:13:181
Tue May 15 19:03:54 [rsSync] replSet rollback findcommonpoint scanned : 6472020
Tue May 15 19:03:54 [rsSync] replSet replSet rollback 3 fixup

Plus tard, pour une raison quelconque, un autre retour en arrière se produit ...

Tue May 15 22:14:24 [rsSync] replSet rollback re-get objects: 13410 replSet too much data to roll back
Tue May 15 22:14:26 [rsSync] replSet syncThread: 13410 replSet too much data to roll back
Tue May 15 22:14:37 [rsSync] replSet syncing to: rs1m2.c9w.co:27017
Tue May 15 22:14:37 [rsSync] replSet syncThread: 13106 nextSafe(): { $err: "capped cursor overrun during query: local.oplog.rs", code: 13338 }
Tue May 15 22:14:48 [rsSync] replSet syncing to: rs1m2.c9w.co:27017
Tue May 15 22:15:30 [rsSync] replSet our last op time written: May 15 19:00:51:6
Tue May 15 22:15:30 [rsSync] replSet rollback 0
Tue May 15 22:15:30 [rsSync] replSet rollback 1
Tue May 15 22:15:30 [rsSync] replSet rollback 2 FindCommonPoint
Tue May 15 22:15:30 [rsSync] replSet info rollback our last optime:   May 15 19:00:51:6
Tue May 15 22:15:30 [rsSync] replSet info rollback their last optime: May 15 22:15:30:9
Tue May 15 22:15:30 [rsSync] replSet info rollback diff in end of log times: -11679 seconds
# More warnings matching the above warnings
Tue May 15 22:17:30 [rsSync] replSet rollback found matching events at May 15 15:59:13:181
Tue May 15 22:17:30 [rsSync] replSet rollback findcommonpoint scanned : 7628640
Tue May 15 22:17:30 [rsSync] replSet replSet rollback 3 fixup

Les seules informations utiles sur les rollbacks que j'ai trouvées sont ces notes qui ne traitent pas du "coincé dans la situation de rollback". http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollbacks/

Lorsqu'une instance MongoDB entre dans un état de restauration et que les données de restauration sont supérieures à 300 Mo de données, vous devez intervenir manuellement. Il restera dans un état de restauration jusqu'à ce que vous preniez des mesures pour enregistrer / supprimer / déplacer ces données, les (désormais secondaires) doivent ensuite être resynchronisées pour les remettre en ligne avec les données primaires. Cela ne doit pas être une resynchronisation complète, mais c'est le moyen le plus simple.

Les annulations multiples sont un symptôme plutôt que la cause d'un problème. La restauration se produit uniquement lorsqu'un secondaire qui n'était pas synchronisé (en raison d'un décalage ou d'un problème de réplication) devient principal et prend des écritures. Donc, les problèmes qui provoquent cela se produisent en premier lieu, ce dont vous devez vous occuper - la restauration elle-même est quelque chose que vous devez traiter en tant qu'administrateur - il y a trop d'embûches potentielles pour que MongoDB réconcilie automatiquement les données.

Si vous souhaitez simuler à nouveau cela à des fins de test, j'ai expliqué comment le faire ici:

http://comerford.cc/2012/05/28/simulating-rollback-on-mongodb/

Finalement, ces données seront stockées dans une collection (dans la base de données locale) plutôt que sauvegardées sur disque, ce qui offrira des opportunités pour les traiter plus efficacement:

https://jira.mongodb.org/browse/SERVER-4375

Pour le moment cependant, une fois qu'un rollback se produit, comme vous l'avez constaté, une intervention manuelle est requise.

Enfin, le manuel contient maintenant des informations similaires au blog de Kristina:

https://docs.mongodb.com/manual/core/replica-set-rollbacks

La «solution» que nous avons finalement utilisée consistait à arroser complètement notre base de données sur la machine qui était bloquée en ROLLBACKmode et à permettre au nouvel effacé SECONDARYde se resynchroniser du maître. Cela semble être une solution sous-optimale car, pour autant que je sache, nous avions encore beaucoup d'espace sur le oplogserveur, donc les machines auraient dû, en théorie, pouvoir se resynchroniser.

J'espère que quelqu'un trouvera une meilleure réponse à cela.