[
https://issues.apache.org/jira/browse/HBASE-23079?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16940268#comment-16940268
]
Xiaolin Ha commented on HBASE-23079:
------------------------------------
[~zhangduo] you showed failed at SPLIT_TABLE_REGION_UPDATE_META, I think it was
a failed step in rollback, and there is other steps failed logs,
{quote}; ServerCrashProcedure
server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true, meta=true
exec-time=45.7260sec
[work@c3-hadoop-srv-ct30 haxiaolin]$ grep 'Uncaught runtime exception for
pid=56653' hbase.4500.log
2019-08-29,01:40:44,883 ERROR [PEWorker-7]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=56653,
state=FAILED:SPLIT_TABLE_REGION_OPEN_CHILD_REGIONS, locked=true,
exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 20.1700sec; SplitTableRegionProcedure
table=c3prck8smonitorc3:tsdb-service, parent=67aead237772eeb491845afdd02037eb,
daughterA=fc85d08d8630ed25715730ba3d6901cb,
daughterB=413a5199ff68f3505f490c8341efe459
2019-08-29,01:40:44,985 ERROR [PEWorker-7]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=56653,
state=FAILED:SPLIT_TABLE_REGION_PRE_OPERATION_AFTER_META, locked=true,
exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 20.1700sec; SplitTableRegionProcedure
table=c3prck8smonitorc3:tsdb-service, parent=67aead237772eeb491845afdd02037eb,
daughterA=fc85d08d8630ed25715730ba3d6901cb,
daughterB=413a5199ff68f3505f490c8341efe459
2019-08-29,01:40:45,086 ERROR [PEWorker-7]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=56653, state=FAILED:SPLIT_TABLE_REGION_UPDATE_META,
locked=true, exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException
via ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 20.1700sec; SplitTableRegionProcedure
table=c3prck8smonitorc3:tsdb-service, parent=67aead237772eeb491845afdd02037eb,
daughterA=fc85d08d8630ed25715730ba3d6901cb,
daughterB=413a5199ff68f3505f490c8341efe459
2019-08-29,01:40:45,188 ERROR [PEWorker-7]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=56653,
state=FAILED:SPLIT_TABLE_REGION_PRE_OPERATION_BEFORE_META, locked=true,
exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 20.1700sec; SplitTableRegionProcedure
table=c3prck8smonitorc3:tsdb-service, parent=67aead237772eeb491845afdd02037eb,
daughterA=fc85d08d8630ed25715730ba3d6901cb,
daughterB=413a5199ff68f3505f490c8341efe459
{quote}
I found there is also SCP in this master's log, and the expired server is
{color:#FF0000}c3-hadoop-srv-st297.bj{color}, which was assigned
{color:#FF0000}413a5199ff68f3505f490c8341efe459{color}, but can not find any
log of detection for expiration of this server like "Processing expiration
of", so I think this SCP was loaded from store.
{quote}2019-08-29,01:43:33,133 ERROR [PEWorker-3]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=55625, state=FAILED:SERVER_CRASH_ASSIGN, locked=true,
exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 25.2950sec; ServerCrashProcedure
server=c3-hadoop-srv-st297.bj,21600,1566990031242, splitWal=true, meta=true
java.lang.UnsupportedOperationException: unhandled state=SERVER_CRASH_FINISH
2019-08-29,01:43:33,236 ERROR [PEWorker-3]
org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
runtime exception for pid=55625, state=FAILED:SERVER_CRASH_SPLIT_LOGS,
locked=true, exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException
via ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
Operation timed out after 25.2950sec; ServerCrashProcedure
server=c3-hadoop-srv-st297.bj,21600,1566990031242, splitWal=true, meta=true
java.lang.UnsupportedOperationException: unhandled state=SERVER_CRASH_ASSIGN
{quote}
So I guess a situation,
a STRP added a children ORP, ORP want to open region on RS st297, but st297
crashed and didn't send open report. Then Master also crashed. Active master
initialed successfully after more than 20secs, loaded stored SRP, ORP, and SCP,
but OPR thinks it was timeout(more than 20secs elapse from submitted time), OPR
failed, rolled back ORP, STRP failed, SCP was also failed by NPE, just like a
dead lock occured.
To verify this guess, I found master started log,
{quote}2019-08-29,01:40:06,213 INFO
[master/c3-hadoop-srv-ct30:21500:becomeActiveMaster]
org.apache.hadoop.hbase.master.ActiveMasterManager: Registered as active
master=c3-hadoop-srv-ct30.bj,21500,1566996542942
{quote}
> SCP fails when PE executes rollback of ORP
> -------------------------------------------
>
> Key: HBASE-23079
> URL: https://issues.apache.org/jira/browse/HBASE-23079
> Project: HBase
> Issue Type: Bug
> Reporter: Xiaolin Ha
> Assignee: Xiaolin Ha
> Priority: Major
>
> In our test environment, we found that, when OpenRegionProcedure failed by
> timeout, though it doesn't support rollback, ProcedureExcutor will delete the
> OPR node in the store in its own rollback steps and make the RIT stay there
> looping rollback exception. ServerCrashProcedure will detect this RIT but
> cannot deal with it, because no node in the store and it will encounters NPE,
> as a result, SCP aborts.
>
> Logs are as follows,
> {quote}2019-08-29,07:27:35,710 INFO [PEWorker-15]
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure: pid=70206,
> state=RUNNABLE:SERVER_CRASH_ASSIGN, locked=true; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true, meta=true
> found RIT pid=56043, ppid=55625, state=ROLLEDBACK;
> TransitRegionStateProcedure table=c3srv_galaxy:tsdb,
> region=c1ccd94593bf1b87269cec98d6ffaaae, ASSIGN; rit=OPEN,
> location=c3-hadoop-srv-st297.bj,21600,1567012736142, table=c3srv_galaxy:tsdb,
> region=c1ccd94593bf1b87269cec98d6ffaaae
> 2019-08-29,07:27:35,711 ERROR [PEWorker-15]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception: pid=70206, state=RUNNABLE:SERVER_CRASH_ASSIGN,
> locked=true; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true, meta=true
> java.lang.NullPointerException
> at
> org.apache.hadoop.hbase.procedure2.store.ProcedureStoreTracker.update(ProcedureStoreTracker.java:140)
> at
> org.apache.hadoop.hbase.procedure2.store.ProcedureStoreTracker.update(ProcedureStoreTracker.java:133)
> at
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore.updateStoreTracker(WALProcedureStore.java:782)
> at
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore.pushData(WALProcedureStore.java:737)
> at
> org.apache.hadoop.hbase.procedure2.store.wal.WALProcedureStore.update(WALProcedureStore.java:604)
> at
> org.apache.hadoop.hbase.master.assignment.RegionRemoteProcedureBase.persistAndWake(RegionRemoteProcedureBase.java:182)
> at
> org.apache.hadoop.hbase.master.assignment.RegionRemoteProcedureBase.serverCrashed(RegionRemoteProcedureBase.java:239)
> at
> org.apache.hadoop.hbase.master.assignment.TransitRegionStateProcedure.serverCrashed(TransitRegionStateProcedure.java:398)
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.assignRegions(ServerCrashProcedure.java:461)
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.executeFromState(ServerCrashProcedure.java:221)
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.executeFromState(ServerCrashProcedure.java:64)
> at
> org.apache.hadoop.hbase.procedure2.StateMachineProcedure.execute(StateMachineProcedure.java:189)
> at org.apache.hadoop.hbase.procedure2.Procedure.doExecute(Procedure.java:962)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.execProcedure(ProcedureExecutor.java:1645)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1392)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$1100(ProcedureExecutor.java:78)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1962)
> 2019-08-29,07:27:35,714 ERROR [PEWorker-15]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=70206, state=FAILED:SERVER_CRASH_SPLIT_LOGS,
> locked=true, exception=java.lang.NullPointerException via CODE-BUG: Uncaught
> runtime exception: pid=70206, state=RUNNABLE:SERVER_CRASH_ASSIGN,
> locked=true; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true,
> meta=true:java.lang.NullPointerException; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true, meta=true
> java.lang.UnsupportedOperationException: unhandled state=SERVER_CRASH_ASSIGN
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:333)
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:64)
> at
> org.apache.hadoop.hbase.procedure2.StateMachineProcedure.rollback(StateMachineProcedure.java:208)
> at
> org.apache.hadoop.hbase.procedure2.Procedure.doRollback(Procedure.java:979)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1566)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeRollback(ProcedureExecutor.java:1498)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1349)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$1100(ProcedureExecutor.java:78)
> at
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1962)
> 2019-08-29,07:27:35,716 ERROR [PEWorker-15]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=70206, state=FAILED:SERVER_CRASH_GET_REGIONS,
> locked=true, exception=java.lang.NullPointerException via CODE-BUG: Uncaught
> runtime exception: pid=70206, state=RUNNABLE:SERVER_CRASH_ASSIGN,
> locked=true; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true,
> meta=true:java.lang.NullPointerException; ServerCrashProcedure
> server=c3-hadoop-srv-st297.bj,21600,1567012736142, splitWal=true, meta=true
> java.lang.UnsupportedOperationException: unhandled
> state=SERVER_CRASH_SPLIT_LOGS
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:333)
> at
> org.apache.hadoop.hbase.master.procedure.ServerCrashProcedure.rollbackState(ServerCrashProcedure.java:64)
> at
> org.apache.hadoop.hbase.procedure2.StateMachineProcedure.rollback(StateMachineProcedure.java:208)
> at
> org.apache.hadoop.hbase.procedure2.Procedure.doRollback(Procedure.java:979)
> {quote}
>
> -------------
> {quote}[work@c3-hadoop-srv-ct30 log]$ grep 'pid=56659' *
> hbase.4500.log:2019-08-29,01:40:31,103 INFO
> [master/c3-hadoop-srv-ct30:21500:becomeActiveMaster]
> org.apache.hadoop.hbase.master.procedure.MasterProcedureScheduler: Took xlock
> for pid=56659, ppid=56653,
> state=WAITING:REGION_STATE_TRANSITION_CONFIRM_OPENED;
> TransitRegionStateProcedure table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459, ASSIGN
> hbase.4500.log:2019-08-29,01:40:31,107 INFO
> [master/c3-hadoop-srv-ct30:21500:becomeActiveMaster]
> org.apache.hadoop.hbase.procedure2.TimeoutExecutorThread: ADDED pid=56661,
> ppid=56659, state=WAITING_TIMEOUT;
> org.apache.hadoop.hbase.master.assignment.OpenRegionProcedure; timeout=1006,
> timestamp=1567014012995
> hbase.4500.log:2019-08-29,01:40:31,186 INFO
> [master/c3-hadoop-srv-ct30:21500:becomeActiveMaster]
> org.apache.hadoop.hbase.master.assignment.AssignmentManager: Attach
> pid=56659, ppid=56653, state=WAITING:REGION_STATE_TRANSITION_CONFIRM_OPENED;
> TransitRegionStateProcedure table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459, ASSIGN to rit=OFFLINE,
> location=null, table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459 to restore RIT
> hbase.4500.log:2019-08-29,01:40:31,676 INFO [PEWorker-16]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: LOCK_EVENT_WAIT
> rollback...pid=56661, ppid=56659, state=FAILED,
> exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
> ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
> Operation timed out after 19.6860sec;
> org.apache.hadoop.hbase.master.assignment.OpenRegionProcedure
> hbase.4500.log:2019-08-29,01:40:43,155 ERROR [PEWorker-7]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=56661, ppid=56659, state=FAILED, locked=true,
> exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
> ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
> Operation timed out after 19.6860sec;
> org.apache.hadoop.hbase.master.assignment.OpenRegionProcedure
> hbase.4500.log:2019-08-29,01:40:43,759 ERROR [PEWorker-7]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=56661, ppid=56659, state=FAILED, locked=true,
> exception=org.apache.hadoop.hbase.exceptions.TimeoutIOException via
> ProcedureExecutor:org.apache.hadoop.hbase.exceptions.TimeoutIOException:
> Operation timed out after 19.6860sec;
> org.apache.hadoop.hbase.master.assignment.OpenRegionProcedure
> hbase.4500.log:2019-08-29,01:40:44,064 ERROR [PEWorker-7]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=56659, ppid=56653,
> state=WAITING:REGION_STATE_TRANSITION_OPEN, locked=true;
> TransitRegionStateProcedure table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459, ASSIGN
> hbase.4500.log:2019-08-29,01:40:44,471 INFO [PEWorker-7]
> org.apache.hadoop.hbase.master.procedure.MasterProcedureScheduler: Took xlock
> for pid=56659, ppid=56653, state=WAITING:REGION_STATE_TRANSITION_OPEN;
> TransitRegionStateProcedure table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459, ASSIGN
> hbase.4500.log:2019-08-29,01:40:44,573 ERROR [PEWorker-7]
> org.apache.hadoop.hbase.procedure2.ProcedureExecutor: CODE-BUG: Uncaught
> runtime exception for pid=56659, ppid=56653,
> state=WAITING:REGION_STATE_TRANSITION_GET_ASSIGN_CANDIDATE, locked=true;
> TransitRegionStateProcedure table=c3prck8smonitorc3:tsdb-service,
> region=413a5199ff68f3505f490c8341efe459, ASSIGN
> {quote}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
