[
https://issues.apache.org/jira/browse/HBASE-20152?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16395573#comment-16395573
]
stack commented on HBASE-20152:
-------------------------------
bq. Just ask, after restarting we will re-schedule a SCP right?
bq. So the SCP is suspended? This is a little confusing to me... I think SCP is
for a crashed server? Why is it suspended?
Thanks for review. Yeah, after master restarting, we'll poke the fs and look
for WALs that do not belong to an existing server. If we find any, we schedule
a SCP.
The SCP processing is 'suspended' at two points during Master's lifetime; 1.
during master start we put the handling of expired znodes aside until meta is
assigned; and 2. when master has been stopped... we skip creating an SCP
depending on Master restart finding any unprocessed crashed servers.
My description gave impression that we stop SCP and that there might be a hole
where we'd miss server crashes. Your questioning made me go back and check...
maybe I should just allow queuing of SCPs even if master is going down... will
look at it.
bq. I do not think we should abandon it. ...
Yeah, took me a while but I came back to here; the attached patch will now find
any unassigns and interrupt them letting them complete if makes sense (they
were unassigns against the crashed server).
> [AMv2] DisableTableProcedure versus ServerCrashProcedure
> --------------------------------------------------------
>
> Key: HBASE-20152
> URL: https://issues.apache.org/jira/browse/HBASE-20152
> Project: HBase
> Issue Type: Bug
> Components: amv2
> Reporter: stack
> Assignee: stack
> Priority: Major
>
> Seeing a small spate of issues where disabled tables/regions are being
> assigned. Usually they happen when a DisableTableProcedure is running
> concurrent with a ServerCrashProcedure. See below. See associated
> HBASE-20131. This is umbrella issue for fixing.
> h3. Deadlock
> From HBASE-20137, 'TestRSGroups is Flakey',
> https://issues.apache.org/jira/browse/HBASE-20137?focusedCommentId=16390325&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-16390325
> {code}
> * SCP is running because a server was aborted in test.
> * SCP starts AssignProcedure of region X from crashed server.
> * DisableTable Procedure runs because test has finished and we're doing
> table delete. Queues
> * UnassignProcedure for region X.
> * Disable Unassign gets Lock on region X first.
> * SCP AssignProcedure tries to get lock, waits on lock.
> * DisableTable Procedure UnassignProcedure RPC fails because server is down
> (Thats why the SCP).
> * Tries to expire the server it failed the RPC against. Fails (currently
> being SCP'd).
> * DisableTable Procedure Unassign is suspended. It is a suspend with lock on
> region X held
> * SCP can't run because lock on X is held
> * Test timesout.
> {code}
> Here is the actual log from around the deadlock. pid=308 is the SCP. pid=309
> is the disable table:
> {code}
> 2018-03-05 11:29:21,224 DEBUG [PEWorker-7]
> procedure.ServerCrashProcedure(225): Done splitting WALs pid=308,
> state=RUNNABLE:SERVER_CRASH_SPLIT_LOGS; ServerCrashProcedure
> server=1cfd208ff882,40584,1520249102524, splitWal=true, meta=false
> 2018-03-05 11:29:21,300 INFO
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> rsgroup.RSGroupAdminServer(371): Move server done: default=>appInfo
> 2018-03-05 11:29:21,307 INFO
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> rsgroup.RSGroupAdminEndpoint$RSGroupAdminServiceImpl(279):
> Client=jenkins//172.17.0.2 list rsgroup
> 2018-03-05 11:29:21,312 INFO [Time-limited test] client.HBaseAdmin$15(901):
> Started disable of Group_ns:testKillRS
> 2018-03-05 11:29:21,313 INFO
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> master.HMaster$7(2278): Client=jenkins//172.17.0.2 disable Group_ns:testKillRS
> 2018-03-05 11:29:21,384 INFO [PEWorker-9]
> procedure2.ProcedureExecutor(1495): Initialized subprocedures=[{pid=310,
> ppid=308, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043}]
> 2018-03-05 11:29:21,534 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> procedure2.ProcedureExecutor(865): Stored pid=309,
> state=RUNNABLE:DISABLE_TABLE_PREPARE; DisableTableProcedure
> table=Group_ns:testKillRS
> 2018-03-05 11:29:21,542 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> master.MasterRpcServices(1134): Checking to see if procedure is done pid=309
> 2018-03-05 11:29:21,644 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> master.MasterRpcServices(1134): Checking to see if procedure is done pid=309
> 2018-03-05 11:29:21,847 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> master.MasterRpcServices(1134): Checking to see if procedure is done pid=309
> 2018-03-05 11:29:22,118 DEBUG [PEWorker-5] hbase.MetaTableAccessor(1944): Put
> {"totalColumns":1,"row":"Group_ns:testKillRS","families":{"table":[{"qualifier":"state","vlen":2,"tag":[],"timestamp":1520249362117}]},"ts":1520249362117}
> 2018-03-05 11:29:22,123 INFO [PEWorker-5] hbase.MetaTableAccessor(1646):
> Updated table Group_ns:testKillRS state to DISABLING in META
> 2018-03-05 11:29:22,148 DEBUG
> [RpcServer.default.FPBQ.Fifo.handler=2,queue=0,port=38498]
> master.MasterRpcServices(1134): Checking to see if procedure is done pid=309
> 2018-03-05 11:29:22,345 INFO [PEWorker-5]
> procedure2.ProcedureExecutor(1495): Initialized subprocedures=[{pid=311,
> ppid=309, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524}]
> 2018-03-05 11:29:22,503 INFO [PEWorker-13]
> procedure.MasterProcedureScheduler(571): pid=311, ppid=309,
> state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524,
> Group_ns:testKillRS,,1520249357742.de7534c208a06502537cd95c248b3043.
> 2018-03-05 11:29:22,503 INFO [PEWorker-5]
> procedure.MasterProcedureScheduler(571): pid=310, ppid=308,
> state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> Group_ns:testKillRS,,1520249357742.de7534c208a06502537cd95c248b3043.
> 2018-03-05 11:29:22,504 INFO [PEWorker-13] assignment.RegionStateStore(189):
> pid=311 updating hbase:meta
> row=Group_ns:testKillRS,,1520249357742.de7534c208a06502537cd95c248b3043.,
> regionState=CLOSING, regionLocation=1cfd208ff882,40584,1520249102524
> 2018-03-05 11:29:22,504 DEBUG [PEWorker-5]
> assignment.RegionTransitionProcedure(377): LOCK_EVENT_WAIT pid=310
> serverLocks={}, namespaceLocks={}, tableLocks={},
> regionLocks={{de7534c208a06502537cd95c248b3043=exclusiveLockOwner=311,
> sharedLockCount=0, waitingProcCount=1}}, peerLocks={}
> 2018-03-05 11:29:22,504 DEBUG [PEWorker-5]
> procedure2.ProcedureExecutor(1230): LOCK_EVENT_WAIT pid=310, ppid=308,
> state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043
> 2018-03-05 11:29:22,507 INFO [PEWorker-13]
> assignment.RegionTransitionProcedure(213): Dispatch pid=311, ppid=309,
> state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524; rit=CLOSING,
> location=1cfd208ff882,40584,1520249102524
> 2018-03-05 11:29:22,508 WARN [PEWorker-13]
> assignment.RegionTransitionProcedure(187): Remote call failed pid=311,
> ppid=309, state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524; rit=CLOSING,
> location=1cfd208ff882,40584,1520249102524; exception=pid=311, ppid=309,
> state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524 to 1cfd208ff882,40584,1520249102524
> 2018-03-05 11:29:22,508 WARN [PEWorker-13]
> assignment.UnassignProcedure(276): Expiring server pid=311, ppid=309,
> state=RUNNABLE:REGION_TRANSITION_DISPATCH; UnassignProcedure
> table=Group_ns:testKillRS, region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524; rit=CLOSING,
> location=1cfd208ff882,40584,1520249102524,
> exception=org.apache.hadoop.hbase.master.assignment.FailedRemoteDispatchException:
> pid=311, ppid=309, state=RUNNABLE:REGION_TRANSITION_DISPATCH;
> UnassignProcedure table=Group_ns:testKillRS,
> region=de7534c208a06502537cd95c248b3043,
> server=1cfd208ff882,40584,1520249102524 to 1cfd208ff882,40584,1520249102524
> {code}
> It disable table procedure unassign and the SCP assign arrive at same time,
> in same ms (2018-03-05 11:29:22,503) but the unassign manages to get the lock
> first.
> h3. Delete of online Regions
> Saw this in nightly failure #452 for branch-2 in
> TestSplitTransactionOnCluster.org.apache.hadoop.hbase.regionserver.TestSplitTransactionOnCluster
> {code}
> * DisableTableProcedure is queued before SCP.
> * DisableTableProcedure Unassign fails because can't RPC to crashed server
> and can't expire.
> * Unassign is Stuck in suspend.
> * SCP runs and cleans up suspended Disable Unassign.
> * SCP completes which includes assign of Disable Unassign region.
> * Disable Unassign completes
> * Disable completes.
> * A scheduled Drop Table Procedure runs (its end of test).
> * Succeeds deleting regions that are actually assigned (see above where SCP
> assigned region).
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
