Zestaw repliki MongoDB WTÓRNY Utknął w stanie `ROLLBACK`

Podczas ostatniej zautomatyzowanej aktualizacji naszego mongodb PRIMARY, kiedy PRIMARYustąpił, na stałe weszło w ROLLBACKstan.

Po kilku godzinach w ROLLBACKstanie nadal nie było .bsonpliku rollbackprzywracania w katalogu w katalogu bazy danych mongodb. To, a także ten wiersz w naszym pliku dziennika: [rsSync] replSet syncThread: 13410 replSet too much data to roll backwydaje się wskazywać, że ROLLBACKproces się nie powiódł.

Chciałbym pomóc w analizie tego, co dokładnie poszło nie tak.

• Wygląda na to, że w naszych dziennikach wystąpiły dwa różne wycofania. Czy to przypadek, czy to zajęło 3 godziny?
• Jeśli pierwsze wycofanie (o godzinie 19:00) zakończyło się powodzeniem, dlaczego nic nie pojawiło się w rollbackkatalogu ou ?
• Zgadnij, co jest przyczyną wszystkich ostrzeżeń? Czy może to być związane z niepowodzeniem przywracania?
• Czy straciliśmy 18 sekund danych z powodu pierwszego ROLLBACK?
• Czy istnieje ogólne rozwiązanie problemu „utknięcia w ROLLBACKstanie”? Skończyło się na tym, że musieliśmy podłączyć cały DB i ponownie zsynchronizować z podstawowym.

Odpowiednie wiersze dziennika to:

# 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

Potem z jakiegoś powodu następuje kolejne wycofanie ...

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

Jedyne przydatne informacje na temat wycofywania, które znalazłem, to te notatki, które nie odnoszą się do „utknięcia w sytuacji wycofania”. http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollbacks/

Gdy instancja MongoDB przechodzi w stan wycofywania, a dane wycofywania są większe niż 300 MB danych, należy ręcznie interweniować. Pozostanie w stanie wycofania, dopóki nie podejmiesz działań w celu zapisania / usunięcia / przeniesienia tych danych, a następnie (teraz drugorzędne) należy ponownie zsynchronizować, aby przywrócić je do pierwotnego. Nie musi to być pełna resynchronizacja, ale jest to najprostszy sposób.

Wielokrotne wycofywanie jest raczej symptomem niż przyczyną problemu. Wycofywanie ma miejsce tylko wtedy, gdy element dodatkowy, który nie był zsynchronizowany (z powodu opóźnienia lub problemu z replikacją) staje się podstawowy i przyjmuje zapisy. Tak więc problemy, które powodują, że tak się dzieje, to przede wszystkim to, na co należy zwrócić uwagę - samo wycofanie jest czymś, z czym trzeba sobie poradzić jako administrator - istnieje zbyt wiele potencjalnych pułapek, aby MongoDB mógł automatycznie uzgodnić dane.

Jeśli chcesz to ponownie zasymulować do celów testowych, przedstawiłem tutaj, jak to zrobić:

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

Ostatecznie dane te będą przechowywane w kolekcji (w lokalnej bazie danych), a nie zrzucane na dysk, co stwarza możliwości bardziej skutecznego radzenia sobie z nimi:

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

Jednak w tej chwili, gdy nastąpi wycofanie, jak stwierdzono, wymagana jest ręczna interwencja.

Wreszcie instrukcja zawiera podobne informacje do bloga Kristiny:

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

„Rozwiązaniem”, z którego ostatecznie skorzystaliśmy, było całkowite zawieszenie naszej bazy danych na maszynie, która utknęła w ROLLBACKtrybie i umożliwiła nowo wygaszonemu SECONDARYponowną synchronizację z urządzeniem głównym. To wydaje się być rozwiązaniem nieoptymalnym, ponieważ, o ile mogłem powiedzieć, wciąż mieliśmy dużo miejsca na oplogkomputerach, więc teoretycznie maszyny powinny mogły ponownie się zsynchronizować.

Mam nadzieję, że ktoś znajdzie na to lepszą odpowiedź.