You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "stack (JIRA)" <ji...@apache.org> on 2018/02/27 20:06:00 UTC
[jira] [Commented] (HBASE-20100) TestEnableTableProcedure flakey
[ 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)