Conjunto de réplicas do MongoDB SECONDARY Stuck in `ROLLBACK`

Durante uma atualização automatizada recente do nosso mongodb PRIMARY, quando o desligou , PRIMARYpermaneceu em um ROLLBACKestado permanente .

Após várias horas no ROLLBACKestado, ainda não havia .bsonarquivo de reversão no rollbackdiretório no diretório do banco de dados mongodb. Isso, e também esta linha em nosso arquivo de log:, [rsSync] replSet syncThread: 13410 replSet too much data to roll backparece indicar que o ROLLBACKprocesso falhou.

Gostaria de alguma ajuda para analisar o que exatamente deu errado.

• Parece que duas reversões diferentes ocorreram em nossos logs. É esse o caso ou levou três horas?
• Se a primeira reversão (às 19:00 horas) foi bem-sucedida, por que nada apareceu no rollbackdiretório ou ?
• Algum palpite sobre a causa de todos esses avisos? Isso pode estar relacionado à falha de reversão?
• Perdemos 18 segundos de dados devido ao primeiro ROLLBACK?
• Existe uma solução genérica para o problema "preso no ROLLBACKestado"? Acabamos tendo que manobrar todo o banco de dados e sincronizar novamente do primário.

As linhas de log relevantes são:

# 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

Mais tarde, por algum motivo, ocorre outra reversão ...

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

As únicas informações úteis sobre reversões que encontrei são essas notas que não tratam da situação "presa na reversão". http://www.mongodb.org/display/DOCS/Replica+Sets+-+Rollbacks http://www.snailinaturtleneck.com/blog/2011/01/19/how-to-use-replica-set-rollbacks/

Quando uma instância do MongoDB entra em um estado de Reversão e os dados de reversão são maiores que 300 MB, é necessário intervir manualmente. Ele permanecerá em um estado de reversão até que você execute uma ação para salvar / remover / mover esses dados, o (agora secundário) deve ser ressincronizado para trazê-los de volta para o primário. Isso não precisa ser uma ressincronização completa, mas é a maneira mais simples.

Reversões múltiplas são um sintoma e não a causa de um problema. A reversão ocorre apenas quando um secundário que não estava sincronizado (devido a atraso ou problema com a replicação) se torna primário e realiza gravações. Portanto, os problemas que causam isso acontecer são o que precisa ser resolvido - a reversão em si é algo com o qual você precisa lidar como administrador - existem muitas armadilhas em potencial para o MongoDB reconciliar os dados automaticamente.

Se você deseja simular isso novamente para fins de teste, descrevi como fazê-lo aqui:

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

Eventualmente, esses dados serão armazenados em uma coleção (no banco de dados local) em vez de despejados em disco, o que apresentará oportunidades de lidar com eles de maneira mais eficaz:

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

No momento, porém, quando ocorre uma reversão, como você encontrou, é necessária uma intervenção manual.

Finalmente, o manual contém informações semelhantes ao blog de Kristina agora:

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

A "solução" que usamos foi hospedar completamente nosso banco de dados na máquina que estava travada no ROLLBACKmodo e permitir que os recém-apagados SECONDARYsejam sincronizados novamente a partir do master. Esta parece ser uma solução abaixo do ideal, porque, o mais próximo que pude perceber, ainda tínhamos muito espaço na oplogtela para que, em teoria, as máquinas pudessem sincronizar novamente.

Espero que alguém encontre uma resposta melhor para isso.