[
https://issues.apache.org/jira/browse/HBASE-21422?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16671579#comment-16671579
]
Duo Zhang commented on HBASE-21422:
-----------------------------------
OK for a normal run, the logs are like
{noformat}
2018-10-31 16:18:35,056 DEBUG [PEWorker-1] procedure2.RootProcedureState(153):
Add procedure pid=18, state=RUNNABLE:MERGE_TABLE_REGIONS_UPDATE_META,
hasLock=true; MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[6f20d4988b1871d53d6df758d0a5511d, 0b71dc645b9372546d86c1b6748cfdb8],
forcibly=false as the 14th rollback step
2018-10-31 16:18:35,056 WARN [PEWorker-1]
procedure2.ProcedureExecutor$Testing(123): Toggle KILL before store update to:
true
2018-10-31 16:18:35,305 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180):
Delete
{"totalColumns":1,"row":"testMergeWithoutPONR,,1541002684116.6f20d4988b1871d53d6df758d0a5511d.","families":{"info":[{"qualifier":"","vlen":0,"tag":[],"timestamp":1541002715303}]},"ts":9223372036854775807}
2018-10-31 16:18:35,306 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180):
Delete
{"totalColumns":1,"row":"testMergeWithoutPONR,0,1541002684116.0b71dc645b9372546d86c1b6748cfdb8.","families":{"info":[{"qualifier":"","vlen":0,"tag":[],"timestamp":1541002715303}]},"ts":9223372036854775807}
2018-10-31 16:18:35,306 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180): Put
{"totalColumns":7,"row":"testMergeWithoutPONR,,1541002703492.71129306f8bcd4fab0e8b282d851090f.","families":{"info":[{"qualifier":"regioninfo","vlen":55,"tag":[],"timestamp":1541002715303},{"qualifier":"mergeA","vlen":55,"tag":[],"timestamp":1541002715303},{"qualifier":"mergeB","vlen":56,"tag":[],"timestamp":1541002715303},{"qualifier":"state","vlen":6,"tag":[],"timestamp":1541002715303}]},"ts":1541002715303}
2018-10-31 16:18:35,725 DEBUG [PEWorker-1] procedure2.RootProcedureState(153):
Add procedure pid=18,
state=RUNNABLE:MERGE_TABLE_REGIONS_POST_MERGE_COMMIT_OPERATION, hasLock=true;
MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[6f20d4988b1871d53d6df758d0a5511d, 0b71dc645b9372546d86c1b6748cfdb8],
forcibly=false as the 15th rollback step
2018-10-31 16:18:35,725 WARN [PEWorker-1]
procedure2.ProcedureExecutor$Testing(123): Toggle KILL before store update to:
false
2018-10-31 16:18:35,725 DEBUG [PEWorker-1] procedure2.ProcedureExecutor(1891):
TESTING: Kill BEFORE store update: pid=18,
state=RUNNABLE:MERGE_TABLE_REGIONS_POST_MERGE_COMMIT_OPERATION, hasLock=true;
MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[6f20d4988b1871d53d6df758d0a5511d, 0b71dc645b9372546d86c1b6748cfdb8],
forcibly=false
{noformat}
And for the failed run, the logs are like
{noformat}
2018-10-31 16:21:58,138 DEBUG [PEWorker-1] procedure2.RootProcedureState(153):
Add procedure pid=18, state=RUNNABLE:MERGE_TABLE_REGIONS_UPDATE_META,
hasLock=true; MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[d0a98022e5c56ccb5288538654be5006, 90232103d076130399c5f0254f30ee5b],
forcibly=false as the 14th rollback step
2018-10-31 16:21:58,152 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180):
Delete
{"totalColumns":1,"row":"testMergeWithoutPONR,,1541002909107.d0a98022e5c56ccb5288538654be5006.","families":{"info":[{"qualifier":"","vlen":0,"tag":[],"timestamp":1541002918150}]},"ts":9223372036854775807}
2018-10-31 16:21:58,153 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180):
Delete
{"totalColumns":1,"row":"testMergeWithoutPONR,0,1541002909107.90232103d076130399c5f0254f30ee5b.","families":{"info":[{"qualifier":"","vlen":0,"tag":[],"timestamp":1541002918150}]},"ts":9223372036854775807}
2018-10-31 16:21:58,153 DEBUG [PEWorker-1] hbase.MetaTableAccessor(2180): Put
{"totalColumns":7,"row":"testMergeWithoutPONR,,1541002911554.f3fa54fca3ba1085a6602d2f837a1c03.","families":{"info":[{"qualifier":"regioninfo","vlen":55,"tag":[],"timestamp":1541002918150},{"qualifier":"mergeA","vlen":55,"tag":[],"timestamp":1541002918150},{"qualifier":"mergeB","vlen":56,"tag":[],"timestamp":1541002918150},{"qualifier":"state","vlen":6,"tag":[],"timestamp":1541002918150}]},"ts":1541002918150}
2018-10-31 16:21:58,229 DEBUG [PEWorker-1] procedure2.RootProcedureState(153):
Add procedure pid=18,
state=RUNNABLE:MERGE_TABLE_REGIONS_POST_MERGE_COMMIT_OPERATION, hasLock=true;
MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[d0a98022e5c56ccb5288538654be5006, 90232103d076130399c5f0254f30ee5b],
forcibly=false as the 15th rollback step
2018-10-31 16:21:58,229 WARN [PEWorker-1]
procedure2.ProcedureExecutor$Testing(123): Toggle KILL before store update to:
true
2018-10-31 16:21:58,231 DEBUG [PEWorker-1] procedure2.RootProcedureState(153):
Add procedure pid=18, state=RUNNABLE:MERGE_TABLE_REGIONS_OPEN_MERGED_REGION,
hasLock=true; MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[d0a98022e5c56ccb5288538654be5006, 90232103d076130399c5f0254f30ee5b],
forcibly=false as the 16th rollback step
2018-10-31 16:21:58,231 WARN [PEWorker-1]
procedure2.ProcedureExecutor$Testing(123): Toggle KILL before store update to:
false
2018-10-31 16:21:58,231 DEBUG [PEWorker-1] procedure2.ProcedureExecutor(1891):
TESTING: Kill BEFORE store update: pid=18,
state=RUNNABLE:MERGE_TABLE_REGIONS_OPEN_MERGED_REGION, hasLock=true;
MergeTableRegionsProcedure table=testMergeWithoutPONR,
regions=[d0a98022e5c56ccb5288538654be5006, 90232103d076130399c5f0254f30ee5b],
forcibly=false
{noformat}
You can see that, we miss a "Toggle KILL before store update to:" after adding
the 14th rollback state for the failed run. Strange.
> NPE in TestMergeTableRegionsProcedure.testMergeWithoutPONR
> ----------------------------------------------------------
>
> Key: HBASE-21422
> URL: https://issues.apache.org/jira/browse/HBASE-21422
> Project: HBase
> Issue Type: Bug
> Components: proc-v2
> Reporter: Duo Zhang
> Priority: Major
>
> {noformat}
> 2018-10-31 16:22:01,302 ERROR [Time-limited test]
> assignment.TestMergeTableRegionsProcedure(305): error!
> java.lang.NullPointerException
> at
> org.apache.hadoop.hbase.master.assignment.MergeTableRegionsProcedure.getStateId(MergeTableRegionsProcedure.java:386)
> at
> org.apache.hadoop.hbase.master.assignment.MergeTableRegionsProcedure.getStateId(MergeTableRegionsProcedure.java:84)
> at
> org.apache.hadoop.hbase.procedure2.StateMachineProcedure.getCurrentStateId(StateMachineProcedure.java:276)
> at
> org.apache.hadoop.hbase.master.procedure.MasterProcedureTestingUtility.testRecoveryAndDoubleExecution(MasterProcedureTestingUtility.java:414)
> at
> org.apache.hadoop.hbase.master.assignment.TestMergeTableRegionsProcedure.testMergeWithoutPONR(TestMergeTableRegionsProcedure.java:296)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at
> org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
> at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> at
> org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298)
> at
> org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.lang.Thread.run(Thread.java:748)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
