Replika MongoDB Ditetapkan SECONDARY Terjebak dalam kondisi `ROLLBACK`

Selama pembaruan otomatis baru-baru ini dari mongodb kami PRIMARY, ketika PRIMARYmengundurkan diri secara permanen pergi ke ROLLBACKkeadaan.

Setelah beberapa jam di ROLLBACKnegara bagian, masih belum ada .bsonfile rollback dalam rollbackdirektori di direktori database mongodb. Itu, dan juga baris ini di file log kami:, [rsSync] replSet syncThread: 13410 replSet too much data to roll backtampaknya menunjukkan bahwa ROLLBACKproses gagal.

Saya ingin membantu menganalisis apa yang sebenarnya salah.

• Tampaknya dua rollback berbeda terjadi di log kami. Apakah itu kasusnya atau itu yang memakan waktu 3 jam?
• Jika kembalikan pertama (pukul 19.00) berhasil, mengapa tidak ada yang muncul di rollbackdirektori Anda?
• Adakah tebakan penyebab semua peringatan itu? Mungkinkah itu terkait dengan kegagalan rollback?
• Apakah kami kehilangan data 18 detik karena yang pertama ROLLBACK?
• Apakah ada solusi umum untuk masalah "macet ROLLBACK"? Kami akhirnya harus mengganti seluruh DB kami dan menyinkronkan kembali dari primer.

Baris log yang relevan adalah:

# 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

Kemudian untuk beberapa alasan kemunduran lain terjadi ...

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

Satu-satunya informasi yang berguna tentang rollback yang saya temukan adalah catatan ini yang tidak membahas "macet dalam situasi rollback". http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollback//

Ketika instance MongoDB masuk ke status Rollback, dan data rollback lebih besar dari 300MB data, Anda harus melakukan intervensi secara manual. Itu akan tetap dalam keadaan rollback sampai Anda mengambil tindakan untuk menyimpan / menghapus / memindahkan data itu, (sekarang sekunder) kemudian harus disinkronkan kembali untuk membawanya kembali sejalan dengan primer. Ini tidak harus menjadi sinkronisasi ulang penuh, tetapi itu adalah cara paling sederhana.

Pemutaran berganda lebih merupakan gejala daripada penyebab masalah. Kembalikan hanya terjadi ketika sekunder yang tidak sinkron (baik karena lag atau masalah dengan replikasi) menjadi utama dan mengambil tulisan. Jadi, masalah yang menyebabkan hal itu terjadi di tempat pertama adalah apa yang perlu dijaga - kemunduran itu sendiri adalah sesuatu yang perlu Anda tangani sebagai admin - ada terlalu banyak potensi jebakan bagi MongoDB untuk merekonsiliasi data secara otomatis.

Jika Anda ingin mensimulasikan ini lagi untuk tujuan pengujian, saya telah menguraikan cara melakukannya di sini:

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

Akhirnya, data ini akan disimpan dalam koleksi (dalam DB lokal) daripada dibuang ke disk, yang akan menghadirkan peluang untuk menanganinya lebih efektif:

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

Namun, pada saat ini, begitu kemunduran terjadi, seperti yang Anda temukan, intervensi manual diperlukan.

Akhirnya, manual ini berisi informasi yang mirip dengan blog Kristina sekarang:

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

"Solusi" yang akhirnya kami gunakan benar-benar menyuntikkan database kami pada mesin yang terjebak dalam ROLLBACKmode dan memungkinkan yang baru saja di-blank SECONDARYuntuk melakukan sinkronisasi ulang dari master. Ini sepertinya solusi suboptimal karena, sejauh yang saya tahu, kami masih memiliki banyak ruang oplogsehingga mesin seharusnya, secara teori, dapat melakukan sinkronisasi ulang.

Semoga seseorang akan memberikan jawaban yang lebih baik untuk ini.