MongoDB Replica Set SECONDARY Im `ROLLBACK`-Status stecken

Während eines kürzlichen automatisierten Updates unseres Mongodb PRIMARY, als es PRIMARYzurücktrat, ging es dauerhaft in einen ROLLBACKZustand über.

Nach mehreren Stunden im ROLLBACKStatus befand sich noch keine Rollback- .bsonDatei im rollbackVerzeichnis im Mongodb-Datenbankverzeichnis. Dies und auch diese Zeile in unserer Protokolldatei: [rsSync] replSet syncThread: 13410 replSet too much data to roll backscheinen darauf hinzudeuten, dass der ROLLBACKProzess fehlgeschlagen ist.

Ich hätte gerne Hilfe bei der Analyse, was genau schief gelaufen ist.

• Es scheint, dass in unseren Protokollen zwei verschiedene Rollbacks aufgetreten sind. Ist das der Fall oder hat es 3 Stunden gedauert?
• Wenn der erste Rollback (um 19:00 Uhr) erfolgreich war, warum wurde in Ihrem Verzeichnis nichts angezeigt rollback?
• Irgendwelche Vermutungen über die Ursache all dieser Warnungen? Könnte das mit dem Rollback-Fehler zusammenhängen?
• Haben wir aufgrund des ersten 18 Sekunden Daten verloren ROLLBACK?
• Gibt es eine generische Lösung für das ROLLBACKProblem "festgefahren "? Am Ende mussten wir unsere gesamte Datenbank abspritzen und von der Primärdatenbank neu synchronisieren.

Die relevanten Protokollzeilen sind:

# 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

Dann später aus irgendeinem Grund ein weiterer Rollback ...

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

Die einzigen nützlichen Informationen zu Rollbacks, die ich gefunden habe, sind diese Hinweise, die sich nicht mit der "festgefahrenen Rollback-Situation" befassen. http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollbacks/

Wenn eine MongoDB-Instanz in einen Rollback-Status wechselt und die Rollback-Daten mehr als 300 MB Daten enthalten, müssen Sie manuell eingreifen. Es bleibt in einem Rollback-Zustand, bis Sie Maßnahmen zum Speichern / Entfernen / Verschieben dieser Daten ergreifen. Die (jetzt sekundären) Daten sollten dann erneut synchronisiert werden, um sie wieder mit den primären Daten in Einklang zu bringen. Dies muss keine vollständige Neusynchronisierung sein, aber das ist der einfachste Weg.

Mehrere Rollbacks sind eher ein Symptom als die Ursache eines Problems. Rollback tritt nur auf, wenn eine sekundäre Datei, die nicht synchronisiert war (entweder aufgrund einer Verzögerung oder eines Problems mit der Replikation), primär wird und Schreibvorgänge ausführt. Die Probleme, die dazu führen, dass dies überhaupt passiert, müssen behoben werden - das Rollback selbst ist etwas, mit dem Sie sich als Administrator befassen müssen -, es gibt zu viele potenzielle Fallstricke für MongoDB, um die Daten automatisch abzustimmen.

Wenn Sie dies zu Testzwecken erneut simulieren möchten, habe ich hier Folgendes beschrieben:

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

Letztendlich werden diese Daten in einer Sammlung (in der lokalen Datenbank) gespeichert und nicht auf der Festplatte gespeichert, was Möglichkeiten bietet, effektiver damit umzugehen:

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

Im Moment ist jedoch ein manueller Eingriff erforderlich, sobald ein Rollback auftritt, wie Sie festgestellt haben.

Schließlich enthält das Handbuch jetzt ähnliche Informationen wie Kristinas Blog:

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

Die "Lösung", die wir letztendlich verwendeten, bestand darin, unsere Datenbank vollständig auf dem Computer abzuspritzen, der im ROLLBACKModus steckte , und dem neu ausgeblendeten Computer die SECONDARYerneute Synchronisierung vom Master zu ermöglichen. Dies scheint eine suboptimale Lösung zu sein, da wir, soweit ich das beurteilen konnte, immer noch viel Platz auf oplogdem Computer hatten, sodass die Maschinen theoretisch in der Lage sein sollten, erneut zu synchronisieren.

Hoffentlich findet jemand eine bessere Antwort darauf.