[
https://issues.apache.org/jira/browse/HBASE-20100?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16379211#comment-16379211
]
stack commented on HBASE-20100:
-------------------------------
For posterity, here is the interesting part of the log... Below is a filter on
region name only. We start from a store restart loading up the content of the
meta table...
{code}
2018-02-27 16:27:55,193 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(389): Loading pid=64, ppid=52,
state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c
2018-02-27 16:27:55,196 DEBUG [PEWorker-1] procedure2.ProcedureExecutor(1230):
LOCK_EVENT_WAIT pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_DISPATCH;
AssignProcedure table=testRecoveryAndDoubleExecution,
region=cdc8d2202f4aa4daf381bf1bf2e2fe0c
2018-02-27 16:27:57,465 INFO [Time-limited test]
assignment.RegionStateStore(121): Load hbase:meta entry region={ENCODED =>
cdc8d2202f4aa4daf381bf1bf2e2fe0c, NAME =>
'testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.',
STARTKEY => 'c', ENDKEY => ''} regionState=OPENING
lastHost=104080720bc8,38818,1519748808967
regionLocation=104080720bc8,38818,1519748808967
2018-02-27 16:27:57,643 INFO [PEWorker-1]
procedure.MasterProcedureScheduler(571): pid=64, ppid=52,
state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c,
testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.
2018-02-27 16:27:57,643 INFO [PEWorker-1] assignment.RegionStateStore(189):
pid=64 updating hbase:meta
row=testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.,
regionState=OPENING
2018-02-27 16:27:57,651 INFO [PEWorker-1]
assignment.RegionTransitionProcedure(213): Dispatch pid=64, ppid=52,
state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c;
rit=OPENING, location=104080720bc8,38818,1519748808967
2018-02-27 16:27:57,651 DEBUG
[RpcServer.default.FPBQ.Fifo.handler=3,queue=0,port=33104]
assignment.RegionTransitionProcedure(235): Received report OPENED seqId=0,
pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c;
rit=OPENING, location=104080720bc8,38818,1519748808967
2018-02-27 16:27:57,767 INFO [PEWorker-1] assignment.RegionStateStore(189):
pid=64 updating hbase:meta
row=testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.,
regionState=OPEN, openSeqNum=0, regionLocation=104080720bc8,38818,1519748808967
2018-02-27 16:27:57,770 DEBUG [PEWorker-1] procedure2.ProcedureExecutor(1517):
TESTING: Kill before store update: pid=64, ppid=52, state=SUCCESS;
AssignProcedure table=testRecoveryAndDoubleExecution,
region=cdc8d2202f4aa4daf381bf1bf2e2fe0c
2018-02-27 16:27:57,804 WARN
[RpcServer.default.FPBQ.Fifo.handler=4,queue=0,port=38818]
regionserver.RSRpcServices(1948): Received OPEN for the
region:testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.,
which is already online
2018-02-27 16:27:58,464 DEBUG [Time-limited test]
procedure2.ProcedureExecutor(389): Loading pid=64, ppid=52,
state=RUNNABLE:REGION_TRANSITION_FINISH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c
2018-02-27 16:27:58,468 DEBUG [PEWorker-1] procedure2.ProcedureExecutor(1230):
LOCK_EVENT_WAIT pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_FINISH;
AssignProcedure table=testRecoveryAndDoubleExecution,
region=cdc8d2202f4aa4daf381bf1bf2e2fe0c
2018-02-27 16:28:00,273 INFO [Time-limited test]
assignment.RegionStateStore(121): Load hbase:meta entry region={ENCODED =>
cdc8d2202f4aa4daf381bf1bf2e2fe0c, NAME =>
'testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.',
STARTKEY => 'c', ENDKEY => ''} regionState=OPEN
lastHost=104080720bc8,38818,1519748808967
regionLocation=104080720bc8,38818,1519748808967
2018-02-27 16:28:00,274 INFO [PEWorker-1]
procedure.MasterProcedureScheduler(571): pid=64, ppid=52,
state=RUNNABLE:REGION_TRANSITION_FINISH; AssignProcedure
table=testRecoveryAndDoubleExecution, region=cdc8d2202f4aa4daf381bf1bf2e2fe0c,
testRecoveryAndDoubleExecution,c,1519748855039.cdc8d2202f4aa4daf381bf1bf2e2fe0c.
2018-02-27 16:28:00,275 WARN [PEWorker-1]
assignment.RegionTransitionProcedure(331): Retryable error trying to
transition: pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_FINISH;
AssignProcedure table=testRecoveryAndDoubleExecution,
region=cdc8d2202f4aa4daf381bf1bf2e2fe0c; rit=OPEN,
location=104080720bc8,38818,1519748808967
2018-02-27 16:28:00,395 WARN [PEWorker-1]
assignment.RegionTransitionProcedure(331): Retryable error trying to
transition: pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_FINISH;
AssignProcedure table=testRecoveryAndDoubleExecution,
region=cdc8d2202f4aa4daf381bf1bf2e2fe0c; rit=OPEN,
location=104080720bc8,38818,1519748808967
{code}
> TestEnableTableProcedure flakey
> -------------------------------
>
> Key: HBASE-20100
> URL: https://issues.apache.org/jira/browse/HBASE-20100
> Project: HBase
> Issue Type: Sub-task
> Reporter: stack
> Priority: Major
>
> Failed in the nightly in interesting way.
> https://builds.apache.org/job/HBase%20Nightly/job/branch-2/398/
> A subprocedure of enable table is assigning regions. The test is doing a kill
> of the procedure store to ensure we can handle all state transtions even in
> face of failure. In this case, the kill of PE framework came in the finish of
> the assign procedure AFTER we'd updated hbase:meta and the internal AM state
> moving Region from OPENING to OPEN. Rerunning this step on restoration of the
> AMv2 WAL Store results in....
> {code}
> 2018-02-27 16:28:02,290 WARN [PEWorker-1]
> assignment.RegionTransitionProcedure(331): Retryable error trying to
> transition: pid=64, ppid=52, state=RUNNABLE:REGION_TRANSITION_FINISH;
> AssignProcedure table=testRecoveryAndDoubleExecution,
> region=cdc8d2202f4aa4daf381bf1bf2e2fe0c; rit=OPEN,
> location=104080720bc8,38818,1519748808967
> org.apache.hadoop.hbase.exceptions.UnexpectedStateException: Expected
> [OFFLINE, CLOSED, SPLITTING, SPLIT, OPENING, FAILED_OPEN] so could move to
> OPEN but current state=OPEN
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
