We ran into a pretty hairy problem today that I’d like to bounce off the group. Here’s what happened:
- Our three-node cluster experienced an unclean shutdown recently.
- One of the nodes was corrupted beyond recovery. We failed it over so we can rebalance using the remaining two nodes and then add another node back in to replace the lost one.
- Rebalance is not working due to the analytics service throwing an exception during startup.
Some info about our deployment:
- Couchbase 6.0.1
- Couchbase Autonomous Operator 1.2.2
- Self-manager Kubernetes cluster on AWS
The exception is:
2020-06-02T18:15:28.926Z ERRO CBAS.replication.NcLifecycleCoordinator [Executor-3:ClusterController] 26ecd874ef516a092fed9aef195acc9f failed to complete startup.
org.apache.hyracks.api.exceptions.HyracksDataException: org.apache.asterix.common.exceptions.ACIDException: java.io.IOException: Log file with id(7) was not found. Requested LSN: 1879048192
at org.apache.hyracks.api.exceptions.HyracksDataException.create(HyracksDataException.java:51) ~[hyracks-api.jar:6.0.1-2037]
at org.apache.asterix.app.nc.task.LocalRecoveryTask.perform(LocalRecoveryTask.java:47) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.app.replication.message.RegistrationTasksResponseMessage.handle(RegistrationTasksResponseMessage.java:63) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.messaging.NCMessageBroker.lambda$receivedMessage$0(NCMessageBroker.java:100) ~[asterix-app.jar:6.0.1-2037]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.apache.asterix.common.exceptions.ACIDException: java.io.IOException: Log file with id(7) was not found. Requested LSN: 1879048192
at org.apache.asterix.transaction.management.service.logging.LogReader.getLogFile(LogReader.java:282) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.transaction.management.service.logging.LogReader.refillLogReadBuffer(LogReader.java:168) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.transaction.management.service.logging.LogReader.next(LogReader.java:105) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.startRecoverysAnalysisPhase(RecoveryManager.java:237) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.replayPartitionsLogs(RecoveryManager.java:184) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.startLocalRecovery(RecoveryManager.java:177) ~[asterix-app.jar:6.0.1-2037]
at com.couchbase.analytics.bootstrap.AnalyticsLocalRecoveryManager.startLocalRecovery(AnalyticsLocalRecoveryManager.java:47) ~[cbas-server.jar:6.0.1-2037]
at org.apache.asterix.app.nc.task.LocalRecoveryTask.perform(LocalRecoveryTask.java:45) ~[asterix-app.jar:6.0.1-2037]
... 7 more
Caused by: java.io.IOException: Log file with id(7) was not found. Requested LSN: 1879048192
at org.apache.asterix.transaction.management.service.logging.LogManager.getLogFile(LogManager.java:574) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.transaction.management.service.logging.LogReader.getLogFile(LogReader.java:279) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.transaction.management.service.logging.LogReader.refillLogReadBuffer(LogReader.java:168) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.transaction.management.service.logging.LogReader.next(LogReader.java:105) ~[asterix-transactions.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.startRecoverysAnalysisPhase(RecoveryManager.java:237) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.replayPartitionsLogs(RecoveryManager.java:184) ~[asterix-app.jar:6.0.1-2037]
at org.apache.asterix.app.nc.RecoveryManager.startLocalRecovery(RecoveryManager.java:177) ~[asterix-app.jar:6.0.1-2037]
at com.couchbase.analytics.bootstrap.AnalyticsLocalRecoveryManager.startLocalRecovery(AnalyticsLocalRecoveryManager.java:47) ~[cbas-server.jar:6.0.1-2037]
at org.apache.asterix.app.nc.task.LocalRecoveryTask.perform(LocalRecoveryTask.java:45) ~[asterix-app.jar:6.0.1-2037]
... 7 more
I delved into the AsterixDB site and didn’t find much useful info on how to recover in this situation. The transaction log is clearly in a bad state.
root@couchbase-0001:/opt/couchbase/var/lib/couchbase/data/@analytics/v_iodevice_0/txn-log# ls -l
-rw-rw---- 1 couchbase couchbase 196 May 4 20:55 checkpoint_4
-rw-rw---- 1 couchbase couchbase 196 Jun 2 17:32 checkpoint_5
-rw-rw---- 1 couchbase couchbase 1152 May 4 21:01 transaction_log_5
-rw-rw---- 1 couchbase couchbase 0 Jun 2 17:32 transaction_log_6
We are not using the analytics service. I’d like to figure out how to recover this node so I can unblock rebalance.
UPDATE: I was able to get the pending failover to finish by restarting the affected pod. Rebalance is stuck at 40%… looks like it’s trying to interact with the analytics service which is still misbehaving. Does anyone know how to kill the analytics service on a running cluster? 