You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Sergey Shelukhin (JIRA)" <ji...@apache.org> on 2018/12/18 22:14:00 UTC
[jira] [Updated] (HBASE-21614) RIT recovery with
ServerCrashProcedure is broken in multiple ways
[ https://issues.apache.org/jira/browse/HBASE-21614?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sergey Shelukhin updated HBASE-21614:
-------------------------------------
Description:
Master is restarting after a previous master crashed while recovering some regions from a dead server.
Master recovers RIT for the region, however the RIT has no location (logged, at least) in CONFIRM_CLOSE state. That is a potential problem #1 - confirm where? But that should be covered by meta, so not a big deal, right.
{noformat}
2018-12-17 14:51:14,606 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Attach pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CONFIRM_CLOSED, hasLock=false; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE to rit=OFFLINE, location=null, table=t1, region=region1 to restore RIT
{noformat}
However, in this case ServerCrashProcedure for the server kicks off BEFORE meta is loaded.
That seems to be a problem #2 - it immediately gets regions to later recover, so in this case it gets nothing.
I've grepped our logs for successful cases of SCP interacting with region transition at startup, and in all cases the meta was loaded before SCP.
Seems like a race condition.
{noformat}
2018-12-17 14:51:14,625 INFO [master/:17000:becomeActiveMaster] master.RegionServerTracker: Starting RegionServerTracker; 0 have existing ServerCrashProcedures, 103 possibly 'live' servers, and 1 'splitting'.
2018-12-17 14:51:20,770 INFO [master/:17000:becomeActiveMaster] master.ServerManager: Processing expiration of server1,17020,1544636616174 on ,17000,1545087053243
2018-12-17 14:51:20,921 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Added server1,17020,1544636616174 to dead servers which carryingMeta=false, submitted ServerCrashProcedure pid=111298
2018-12-17 14:51:30,728 INFO [PEWorker-13] procedure.ServerCrashProcedure: Start pid=111298, state=RUNNABLE:SERVER_CRASH_START, hasLock=true; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false
{noformat}
Meta is only loaded 11-12 seconds later.
If one looks at meta-loading code however, there is one more problem - the region is in CLOSING state, so the {{addRegionToServer}} is not going to be called - it's only called for OPENED regions.
Expanding on the above, I've only seen SCP unblock stuck region transition at startup when region started out in meta as OPEN.
{noformat}
2018-12-17 14:51:42,403 INFO [master/:17000:becomeActiveMaster] assignment.RegionStateStore: Load hbase:meta entry region=region1, regionState=CLOSING, lastHost=server1,17020,1544636616174, regionLocation=server1,17020,1544636616174, openSeqNum=629131
{noformat}
SCP predictably finishes without doing anything; no other logs for this pid
{noformat}
2018-12-17 14:52:19,046 INFO [PEWorker-2] procedure2.ProcedureExecutor: Finished pid=111298, state=SUCCESS, hasLock=false; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false in 58.0010sec
{noformat}
After that, region is still stuck trying to be closed in TransitRegionStateProcedure; it's in the same state for hours including across master restarts.
{noformat}
2018-12-17 15:09:35,216 WARN [PEWorker-14] assignment.TransitRegionStateProcedure: Failed transition, suspend 604secs pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CLOSE, hasLock=true; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE; rit=CLOSING, location=server1,17020,1544636616174; waiting on rectified condition fixed by other Procedure or operator intervention
{noformat}
was:
Master is restarting after a previous master crashed while recovering some regions from a dead server.
Master recovers RIT for the region, however the RIT has no location (logged, at least) in CONFIRM_CLOSE state. That is a potential problem #1 - confirm where? But that should be covered by meta, so not a big deal, right.
{noformat}
2018-12-17 14:51:14,606 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Attach pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CONFIRM_CLOSED, hasLock=false; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE to rit=OFFLINE, location=null, table=t1, region=region1 to restore RIT
{noformat}
However, in this case ServerCrashProcedure for the server kicks off BEFORE meta is loaded.
That seems to be a problem #2 - it immediately gets regions to later recover, so in this case it gets nothing.
I've grepped our logs for successful cases of SCP interacting with TRANSITION_CONFIRM_CLOSED, and in all cases the meta was loaded before SCP.
Seems like a race condition.
{noformat}
2018-12-17 14:51:14,625 INFO [master/:17000:becomeActiveMaster] master.RegionServerTracker: Starting RegionServerTracker; 0 have existing ServerCrashProcedures, 103 possibly 'live' servers, and 1 'splitting'.
2018-12-17 14:51:20,770 INFO [master/:17000:becomeActiveMaster] master.ServerManager: Processing expiration of server1,17020,1544636616174 on ,17000,1545087053243
2018-12-17 14:51:20,921 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Added server1,17020,1544636616174 to dead servers which carryingMeta=false, submitted ServerCrashProcedure pid=111298
2018-12-17 14:51:30,728 INFO [PEWorker-13] procedure.ServerCrashProcedure: Start pid=111298, state=RUNNABLE:SERVER_CRASH_START, hasLock=true; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false
{noformat}
Meta is only loaded 11-12 seconds later.
If one looks at meta-loading code however, there is one more problem - the region is in CLOSING state, so the {{addRegionToServer}} is not going to be called - it's only called for OPENED regions.
Expanding on the above, I've only seen SCP unblock stuck TRANSITION_CONFIRM_CLOSED when region started out in meta as OPEN.
{noformat}
2018-12-17 14:51:42,403 INFO [master/:17000:becomeActiveMaster] assignment.RegionStateStore: Load hbase:meta entry region=region1, regionState=CLOSING, lastHost=server1,17020,1544636616174, regionLocation=server1,17020,1544636616174, openSeqNum=629131
{noformat}
SCP predictably finishes without doing anything; no other logs for this pid
{noformat}
2018-12-17 14:52:19,046 INFO [PEWorker-2] procedure2.ProcedureExecutor: Finished pid=111298, state=SUCCESS, hasLock=false; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false in 58.0010sec
{noformat}
After that, region is still stuck trying to be closed in TransitRegionStateProcedure; it's in the same state for hours including across master restarts.
{noformat}
2018-12-17 15:09:35,216 WARN [PEWorker-14] assignment.TransitRegionStateProcedure: Failed transition, suspend 604secs pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CLOSE, hasLock=true; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE; rit=CLOSING, location=server1,17020,1544636616174; waiting on rectified condition fixed by other Procedure or operator intervention
{noformat}
> RIT recovery with ServerCrashProcedure is broken in multiple ways
> -----------------------------------------------------------------
>
> Key: HBASE-21614
> URL: https://issues.apache.org/jira/browse/HBASE-21614
> Project: HBase
> Issue Type: Bug
> Reporter: Sergey Shelukhin
> Priority: Major
>
> Master is restarting after a previous master crashed while recovering some regions from a dead server.
> Master recovers RIT for the region, however the RIT has no location (logged, at least) in CONFIRM_CLOSE state. That is a potential problem #1 - confirm where? But that should be covered by meta, so not a big deal, right.
> {noformat}
> 2018-12-17 14:51:14,606 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Attach pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CONFIRM_CLOSED, hasLock=false; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE to rit=OFFLINE, location=null, table=t1, region=region1 to restore RIT
> {noformat}
> However, in this case ServerCrashProcedure for the server kicks off BEFORE meta is loaded.
> That seems to be a problem #2 - it immediately gets regions to later recover, so in this case it gets nothing.
> I've grepped our logs for successful cases of SCP interacting with region transition at startup, and in all cases the meta was loaded before SCP.
> Seems like a race condition.
> {noformat}
> 2018-12-17 14:51:14,625 INFO [master/:17000:becomeActiveMaster] master.RegionServerTracker: Starting RegionServerTracker; 0 have existing ServerCrashProcedures, 103 possibly 'live' servers, and 1 'splitting'.
> 2018-12-17 14:51:20,770 INFO [master/:17000:becomeActiveMaster] master.ServerManager: Processing expiration of server1,17020,1544636616174 on ,17000,1545087053243
> 2018-12-17 14:51:20,921 INFO [master/:17000:becomeActiveMaster] assignment.AssignmentManager: Added server1,17020,1544636616174 to dead servers which carryingMeta=false, submitted ServerCrashProcedure pid=111298
> 2018-12-17 14:51:30,728 INFO [PEWorker-13] procedure.ServerCrashProcedure: Start pid=111298, state=RUNNABLE:SERVER_CRASH_START, hasLock=true; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false
> {noformat}
> Meta is only loaded 11-12 seconds later.
> If one looks at meta-loading code however, there is one more problem - the region is in CLOSING state, so the {{addRegionToServer}} is not going to be called - it's only called for OPENED regions.
> Expanding on the above, I've only seen SCP unblock stuck region transition at startup when region started out in meta as OPEN.
> {noformat}
> 2018-12-17 14:51:42,403 INFO [master/:17000:becomeActiveMaster] assignment.RegionStateStore: Load hbase:meta entry region=region1, regionState=CLOSING, lastHost=server1,17020,1544636616174, regionLocation=server1,17020,1544636616174, openSeqNum=629131
> {noformat}
> SCP predictably finishes without doing anything; no other logs for this pid
> {noformat}
> 2018-12-17 14:52:19,046 INFO [PEWorker-2] procedure2.ProcedureExecutor: Finished pid=111298, state=SUCCESS, hasLock=false; ServerCrashProcedure server=server1,17020,1544636616174, splitWal=true, meta=false in 58.0010sec
> {noformat}
> After that, region is still stuck trying to be closed in TransitRegionStateProcedure; it's in the same state for hours including across master restarts.
> {noformat}
> 2018-12-17 15:09:35,216 WARN [PEWorker-14] assignment.TransitRegionStateProcedure: Failed transition, suspend 604secs pid=38015, state=RUNNABLE:REGION_STATE_TRANSITION_CLOSE, hasLock=true; TransitRegionStateProcedure table=t1, region=region1, REOPEN/MOVE; rit=CLOSING, location=server1,17020,1544636616174; waiting on rectified condition fixed by other Procedure or operator intervention
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)