MongoDB Replica Set SECUNDARIO Atascado en estado `ROLLBACK`

Durante una reciente actualización automatizada de nuestro mongodb PRIMARY, cuando la PRIMARYbajó, permaneció permanentemente en un ROLLBACKestado.

Después de varias horas en el ROLLBACKestado, todavía no había ningún .bsonarchivo de reversión en el rollbackdirectorio en el directorio de la base de datos mongodb. Eso, y también esta línea en nuestro archivo de registro: [rsSync] replSet syncThread: 13410 replSet too much data to roll backparece indicar que el ROLLBACKproceso falló.

Quisiera ayuda para analizar qué salió mal exactamente.

• Parece que ocurrieron dos retrocesos diferentes en nuestros registros. ¿Es ese el caso o fue uno que tomó 3 horas?
• Si la primera reversión (a las 19:00 horas) fue exitosa, ¿por qué no apareció nada en nuestro rollbackdirectorio?
• ¿Alguna idea de la causa de todas esas advertencias? ¿Podría estar relacionado con la falla de reversión?
• ¿Perdimos 18 segundos de datos debido al primero ROLLBACK?
• ¿Existe una solución genérica para el ROLLBACKproblema del "estado atascado "? Terminamos teniendo que cargar toda nuestra base de datos y volver a sincronizar desde la primaria.

Las líneas de registro relevantes son:

# 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

Luego, por alguna razón, se produce otra reversión ...

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

La única información útil sobre retrocesos que he encontrado son estas notas que no abordan la "situación de retroceso". http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollbacks/

Cuando una instancia de MongoDB entra en un estado Rollback, y los datos de rollback son superiores a 300 MB de datos, debe intervenir manualmente. Permanecerá en un estado de reversión hasta que tome medidas para guardar / eliminar / mover esos datos, el (ahora secundario) debería volver a sincronizarse para volver a alinearlo con el primario. Esto no tiene que ser una resincronización completa, pero esa es la forma más simple.

Las reversiones múltiples son un síntoma más que la causa de un problema. La reversión solo ocurre cuando un secundario que no estaba sincronizado (debido a un retraso o un problema con la replicación) se vuelve primario y toma escrituras. Entonces, los problemas que hacen que eso suceda en primer lugar son los que deben ser atendidos: la reversión en sí es algo con lo que debe lidiar como administrador; existen demasiados obstáculos potenciales para que MongoDB concilie los datos automáticamente.

Si desea simular esto nuevamente con fines de prueba, he esbozado cómo hacerlo aquí:

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

Eventualmente, estos datos se almacenarán en una colección (en la base de datos local) en lugar de descargarse en el disco, lo que presentará oportunidades para tratarlos de manera más efectiva:

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

Sin embargo, por el momento, una vez que se produce una reversión, como descubrió, se requiere intervención manual.

Finalmente, el manual contiene información similar al blog de Kristina ahora:

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

La "solución" que terminamos usando era alojar completamente nuestra base de datos en la máquina, que estaba atascada en ROLLBACKmodo y permitiendo que el nuevo blanco se SECONDARYvolviera a sincronizar desde el maestro. Esto parece una solución subóptima porque, por lo que pude ver, todavía teníamos mucho espacio en el, oplogpor lo que las máquinas deberían haber podido, en teoría, volver a sincronizar.

Esperemos que alguien encuentre una mejor respuesta para esto.