[ASTERIXDB-2130] NPE in RecoveryManager.undo

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Component/s: TX - Transactions
• Assignee: Murtadha Makki Al Hubail
• Reporter: Till Westmann
• Created: 12/Oct/17 15:29
• Updated: 09/Nov/17 18:07
• Resolved: 06/Nov/17 06:26

Description

RecoveryManager.undo throws an NPE, as the result of DatasetLifecycleManager.getIndex is not checked:

12:29:41 Oct 11, 2017 7:30:38 PM org.apache.hyracks.control.cc.executor.JobExecutor notifyTaskComplete
12:29:41 WARNING: Spurious task complete notification: TAID:TID:ANID:ODID:2:0:1:0 Current state = ABORTED
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: undoing loser transaction's effect
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.transaction.management.service.transaction.TransactionManager abortTransaction
12:29:41 SEVERE: Could not complete rollback! System is in an inconsistent state
12:29:41 java.lang.IllegalStateException: Failed to undo
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.undo(RecoveryManager.java:690)
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.rollbackTransaction(RecoveryManager.java:630)
12:29:41 	at org.apache.asterix.transaction.management.service.transaction.TransactionManager.abortTransaction(TransactionManager.java:65)
12:29:41 	at org.apache.asterix.transaction.management.service.transaction.TransactionManager.completedTransaction(TransactionManager.java:132)
12:29:41 	at org.apache.asterix.runtime.job.listener.JobEventListenerFactory$1.jobletFinish(JobEventListenerFactory.java:58)
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: rollbacking transaction log records from 341833971 to 342015311
12:29:41 	at org.apache.hyracks.control.nc.Joblet.performCleanup(Joblet.java:317)
12:29:41 	at org.apache.hyracks.control.nc.Joblet.removeTask(Joblet.java:152)
12:29:41 	at org.apache.hyracks.control.nc.work.NotifyTaskCompleteWork.run(NotifyTaskCompleteWork.java:49)
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: collecting loser transaction's LSNs from 341833971 to 342015311
12:29:41 	at org.apache.hyracks.control.common.work.WorkQueue$WorkerThread.run(WorkQueue.java:127)
12:29:41 Caused by: java.lang.NullPointerException
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.undo(RecoveryManager.java:666)
12:29:41 	... 8 more
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: undoing loser transaction's effect
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.hyracks.control.common.work.WorkQueue$WorkerThread auditWaitsAndBlocks
12:29:41 WARNING: Work NotifyTaskCompleteWork:TAID:TID:ANID:ODID:2:0:3:0 waited 1 times (~0ms), blocked 3 times (~0ms)
12:29:41 Exception in thread "Worker:asterix_nc2" java.lang.Error: org.apache.asterix.common.exceptions.ACIDException: Could not complete rollback! System is in an inconsistent state
12:29:41 	at org.apache.asterix.runtime.job.listener.JobEventListenerFactory$1.jobletFinish(JobEventListenerFactory.java:61)
12:29:41 	at org.apache.hyracks.control.nc.Joblet.performCleanup(Joblet.java:317)
12:29:41 	at org.apache.hyracks.control.nc.Joblet.removeTask(Joblet.java:152)
12:29:41 	at org.apache.hyracks.control.nc.work.NotifyTaskCompleteWork.run(NotifyTaskCompleteWork.java:49)
12:29:41 	at org.apache.hyracks.control.common.work.WorkQueue$WorkerThread.run(WorkQueue.java:127)
12:29:41 Caused by: org.apache.asterix.common.exceptions.ACIDException: Could not complete rollback! System is in an inconsistent state
12:29:41 	at org.apache.asterix.transaction.management.service.transaction.TransactionManager.abortTransaction(TransactionManager.java:73)
12:29:41 	at org.apache.asterix.transaction.management.service.transaction.TransactionManager.completedTransaction(TransactionManager.java:132)
12:29:41 	at org.apache.asterix.runtime.job.listener.JobEventListenerFactory$1.jobletFinish(JobEventListenerFactory.java:58)
12:29:41 	... 4 more
12:29:41 Caused by: java.lang.IllegalStateException: Failed to undo
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.undo(RecoveryManager.java:690)
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.rollbackTransaction(RecoveryManager.java:630)
12:29:41 	at org.apache.asterix.transaction.management.service.transaction.TransactionManager.abortTransaction(TransactionManager.java:65)
12:29:41 	... 6 more
12:29:41 Caused by: java.lang.NullPointerException
12:29:41 	at org.apache.asterix.app.nc.RecoveryManager.undo(RecoveryManager.java:666)
12:29:41 	... 8 more
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: undone loser transaction's effect
12:29:41 Oct 11, 2017 7:30:38 PM org.apache.asterix.app.nc.RecoveryManager rollbackTransaction
12:29:41 INFO: [RecoveryManager's rollback log count] update/entityCommit/undo:761/0/761

Issue Links

• links to: Integration test failure