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
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...