hbase-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Yi Liang (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HBASE-19218) Master stuck thinking hbase:namespace is assigned after restart preventing intialization
Date Wed, 20 Dec 2017 23:06:00 GMT

    [ https://issues.apache.org/jira/browse/HBASE-19218?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16299221#comment-16299221
] 

Yi Liang commented on HBASE-19218:
----------------------------------

I have seen this error in my cluster as well
{quote}
2017-11-08 00:25:25,260 INFO  [ProcExecWrkr-18] procedure.MasterProcedureScheduler: pid=40,
ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94
hbase:namespace hbase:namespace,,1510084256045.f147f204a579b885c351bdc0a7ebbf94.
2017-11-08 00:25:25,263 INFO  [ProcExecWrkr-18] assignment.AssignProcedure: Start pid=40,
ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94;
rit=OFFLINE, location=node_5,16020,1510084579728; forceNewPlan=false, retain=true

.....


2017-11-08 00:25:26,040 INFO  [ProcExecWrkr-23] procedure.ServerCrashProcedure: pid=42 found
RIT pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:namespace,
region=f147f204a579b885c351bdc0a7ebbf94; rit=OPENING, location=node_5,16020,1510100695534
2017-11-08 00:25:26,040 WARN  [ProcExecWrkr-23] assignment.RegionTransitionProcedure: Remote
call failed pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:namespace,
region=f147f204a579b885c351bdc0a7ebbf94; rit=OPENING, location=node_5,16020,1510100695534;
exception=ServerCrashProcedure pid=42, server=node_5,16020,1510100695534
2017-11-08 00:25:26,041 INFO  [ProcExecWrkr-23] assignment.AssignProcedure: Retry=1 of max=10;
pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:namespace,
region=f147f204a579b885c351bdc0a7ebbf94; rit=OPENING, location=node_5,16020,1510100695534
2017-11-08 00:25:26,193 INFO  [ProcExecWrkr-25] zookeeper.MetaTableLocator: Setting hbase:meta
(replicaId=0) location in ZooKeeper as node_2,16020,1510100696388
2017-11-08 00:25:26,195 INFO  [ProcExecWrkr-25] assignment.RegionTransitionProcedure: Dispatch
pid=44, ppid=43, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:meta,
region=1588230740; rit=OPENING, location=node_2,16020,1510100696388
2017-11-08 00:25:26,346 INFO  [ProcedureDispatcherTimeoutThread] procedure.RSProcedureDispatcher:
Using procedure batch rpc execution for serverName=node_2,16020,1510100696388 version=2097152
2017-11-08 00:25:27,187 INFO  [ProcExecWrkr-4] hbase.MetaTableAccessor: Updated table hbase:meta
state to ENABLED in META
2017-11-08 00:25:27,187 INFO  [ProcExecWrkr-4] zookeeper.MetaTableLocator: Setting hbase:meta
(replicaId=0) location in ZooKeeper as node_2,16020,1510100696388
2017-11-08 00:25:27,209 INFO  [ProcExecWrkr-22] assignment.RegionTransitionProcedure: Dispatch
pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:namespace,
region=f147f204a579b885c351bdc0a7ebbf94; rit=OFFLINE, location=null
2017-11-08 00:25:27,210 INFO  [ProcExecWrkr-21] assignment.RegionTransitionProcedure: Dispatch
pid=39, ppid=36, state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=hbase:acl,
region=24aadcb52fdc43e2ebcffe95d39b43ab; rit=OPENING, location=node_2,16020,1510100696388
2017-11-08 00:25:27,211 ERROR [ProcExecWrkr-22] procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception: pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94
java.lang.NullPointerException
at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936)
{quote}


I track the AssignProcedure of hbase:namespace to above log

1. AssignProcedure created for table=hbase:namespace; and state is RUNNABLE:REGION_TRANSITION_QUEUE
2. ServerCrashProcedure happens and will handle AssignProcedure of table=hbase:namespace,

   and from the log, this AssignProcedure state has already been set to REGION_TRANSITION_DISPATCH
when SCP handle it. 
   The SCP will set the AssignProcedure back to REGION_TRANSITION_QUEUE and offline related
region.
3. However, The AssignProcedure of hbase:namespace resume from state REGION_TRANSITION_DISPATCH,

   and SCP in step2 has already offline the region and set location as null, so null pointer
exception may happen

The problem happens at step 3 above, the AssignProcedure should resume from state REGION_TRANSITION_QUEUE,
but it actually from REGION_TRANSITION_DISPATCH. 
This could happen, since when SCP call remoteCallFailed for AssignProcedure of hbase:namespace,

ProcedureExecutor is running AssignProcedure of hbase:namespace as state REGION_TRANSITION_DISPATCH
at same time.
and if SCP's handleFailure(which set region location as null) for hbase:namespace happens
before AssignProcedure#addToRemoteDispatcher, and then null pointer happens

  
And if we can catch the nullpointerexception and set state back to REGION_TRANSITION_QUEUE,
that may work for this problem




> Master stuck thinking hbase:namespace is assigned after restart preventing intialization
> ----------------------------------------------------------------------------------------
>
>                 Key: HBASE-19218
>                 URL: https://issues.apache.org/jira/browse/HBASE-19218
>             Project: HBase
>          Issue Type: Bug
>            Reporter: Josh Elser
>            Assignee: Umesh Agashe
>            Priority: Critical
>             Fix For: 2.0.0-beta-1
>
>         Attachments: hbase-hbase-master-ctr-e134-1499953498516-282290-01-000003.hwx.site.log.zip,
hbase-site.xml
>
>
> Our [~romil.choksi] brought this one to my attention after trying to get some cluster
tests running.
> The Master seems to have gotten stuck never initializing after it thinks that hbase:namespace
was already deployed on the cluster when it actually was not. On a Master restart, it reads
the location out of meta and assumes that it's there (I assume this invalid entry is the issue):
> {noformat}
> 2017-11-08 00:29:17,556 INFO  [ctr-e134-1499953498516-282290-01-000003:20000.masterManager]
assignment.RegionStateStore: Load hbase:meta entry region={ENCODED => f147f204a579b885c351bdc0a7ebbf94,
NAME => 'hbase:namespace,,1510084256045.f147f204a579b885c351bdc0a7ebbf94.', STARTKEY =>
'', ENDKEY => ''} regionState=OPENING lastHost=ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728
regionLocation=ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510100695534
> {noformat}
> Prior to this, the RS5 went through the ServerCrashProcedure, but it looks like this
bailed out unexpectedly:
> {noformat}
> 2017-11-08 00:25:25,187 WARN  [ctr-e134-1499953498516-282290-01-000003:20000.masterManager]
master.ServerManager: Expiration of ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728
but server not online
> 2017-11-08 00:25:25,187 INFO  [ProcExecWrkr-5] procedure.ServerCrashProcedure: Start
pid=36, state=RUNNABLE:SERVER_CRASH_START; ServerCrashProcedure server=ctr-e134-1499953498516-282290-01-000003.hwx.site,16020,1510084580111,
splitWal=t
> rue, meta=false
> 2017-11-08 00:25:25,188 INFO  [ctr-e134-1499953498516-282290-01-000003:20000.masterManager]
master.ServerManager: Processing expiration of ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728
on ctr-e134-1499953498516-28
> 2290-01-000003.hwx.site,20000,1510100690324
> ...
> 2017-11-08 00:25:27,211 ERROR [ProcExecWrkr-22] procedure2.ProcedureExecutor: CODE-BUG:
Uncaught runtime exception: pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94
> java.lang.NullPointerException
>         at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936)
>         at org.apache.hadoop.hbase.procedure2.RemoteProcedureDispatcher.addOperationToNode(RemoteProcedureDispatcher.java:171)
>         at org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure.addToRemoteDispatcher(RegionTransitionProcedure.java:223)
>         at org.apache.hadoop.hbase.master.assignment.AssignProcedure.updateTransition(AssignProcedure.java:252)
>         at org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure.execute(RegionTransitionProcedure.java:309)
>         at org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure.execute(RegionTransitionProcedure.java:82)
>         at org.apache.hadoop.hbase.procedure2.Procedure.doExecute(Procedure.java:845)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.execProcedure(ProcedureExecutor.java:1452)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1221)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$800(ProcedureExecutor.java:77)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1731)
> 2017-11-08 00:25:27,239 FATAL [ProcExecWrkr-22] procedure2.ProcedureExecutor: CODE-BUG:
Uncaught runtime exception for pid=37, state=FAILED:SERVER_CRASH_FINISH, exception=java.lang.NullPointerException
via CODE-BUG: Uncaught runtime exception: pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE;
AssignProcedure table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94:java.lang.NullPointerException;
ServerCrashProcedure server=ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728,
splitWal=true, meta=false
> java.lang.UnsupportedOperationException: unhandled state=SERVER_CRASH_FINISH
>         at org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:236)
>         at org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:56)
>         at org.apache.hadoop.hbase.procedure2.StateMachineProcedure.rollback(StateMachineProcedure.java:198)
>         at org.apache.hadoop.hbase.procedure2.Procedure.doRollback(Procedure.java:859)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1353)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1309)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1178)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$800(ProcedureExecutor.java:77)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1731)
> 2017-11-08 00:25:27,344 FATAL [ProcExecWrkr-8] procedure2.ProcedureExecutor: CODE-BUG:
Uncaught runtime exception for pid=37, state=FAILED:SERVER_CRASH_FINISH, exception=java.lang.NullPointerException
via CODE-BUG: Uncaught runtime exception: pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE;
AssignProcedure table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94:java.lang.NullPointerException;
ServerCrashProcedure server=ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728,
splitWal=true, meta=false
> java.lang.UnsupportedOperationException: unhandled state=SERVER_CRASH_FINISH
>         at org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:236)
>         at org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:56)
>         at org.apache.hadoop.hbase.procedure2.StateMachineProcedure.rollback(StateMachineProcedure.java:198)
>         at org.apache.hadoop.hbase.procedure2.Procedure.doRollback(Procedure.java:859)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1353)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1309)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1178)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$800(ProcedureExecutor.java:77)
>         at org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1731)
> 2017-11-08 00:25:27,356 INFO  [ProcExecWrkr-5] procedure2.ProcedureExecutor: Rolled back
pid=37, state=ROLLEDBACK, exception=java.lang.NullPointerException via CODE-BUG: Uncaught
runtime exception: pid=40, ppid=37, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure
table=hbase:namespace, region=f147f204a579b885c351bdc0a7ebbf94:java.lang.NullPointerException;
ServerCrashProcedure server=ctr-e134-1499953498516-282290-01-000005.hwx.site,16020,1510084579728,
splitWal=true, meta=false exec-time=2.1650sec
> {noformat}
> Shortly after this, the master was restarted.
> My hunch is that because the SCP crashed, we never invalidated the meta entries and got
us stuck thinking the region was assigned when it wasn't?



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Mime
View raw message