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

Josh Elser commented on HBASE-18152:
------------------------------------

I think I saw something similar to this, but it may be less of the bug Stack 
outlines and more self-inflicted. I was trying out 2.0.0-rc0 on Hadoop 3.

The version of Hadoop3 I had installed doesn't work with the asyncwal, which I 
noticed after tryign to start up the first time. Then, I realized I needed to 
set the meta-wal provider configuration option in addition to the normal wal 
provider option. IIRC, {{stop-hbase.sh}} hung so I ended up {{kill}}'ing the 
process. This caused a bunch of WAL split failures in the Master to get logged 
around {{2018-04-12 21:43:01}}.

Interestingly, the Master eventually started complaining around the region 
transition that the connection was null (because the server was stopping, I 
assume)
{code:java}
2018-04-12 21:43:05,781 WARN  [PEWorker-8] 
assignment.RegionTransitionProcedure: Retryable error trying to transition: 
pid=3586, ppid=3534, state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure 
table=TestTable, region=0e5c6da974e1d3753ba0cb6a8f0db5b1; rit=OPENING, 
location=ctr-e138-1518143905142-221855-01-000009.hwx.site,16020,1523564755147
java.io.InterruptedIOException: Interrupted after 7 tries while maxAttempts=31
    at 
org.apache.hadoop.hbase.client.RpcRetryingCallerImpl.callWithRetries(RpcRetryingCallerImpl.java:173)
    at org.apache.hadoop.hbase.client.HTable.get(HTable.java:386)
    at org.apache.hadoop.hbase.client.HTable.get(HTable.java:360)
    at 
org.apache.hadoop.hbase.MetaTableAccessor.getTableState(MetaTableAccessor.java:1076)
    at 
org.apache.hadoop.hbase.master.TableStateManager.readMetaState(TableStateManager.java:213)
    at 
org.apache.hadoop.hbase.master.TableStateManager.getTableState(TableStateManager.java:191)
    at 
org.apache.hadoop.hbase.master.assignment.AssignProcedure.startTransition(AssignProcedure.java:163)
    at 
org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure.execute(RegionTransitionProcedure.java:295)
    at 
org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure.execute(RegionTransitionProcedure.java:85)
    at 
org.apache.hadoop.hbase.procedure2.Procedure.doExecute(Procedure.java:845)
    at 
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.execProcedure(ProcedureExecutor.java:1453)
    at 
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.executeProcedure(ProcedureExecutor.java:1221)
    at 
org.apache.hadoop.hbase.procedure2.ProcedureExecutor.access$800(ProcedureExecutor.java:75)
    at 
org.apache.hadoop.hbase.procedure2.ProcedureExecutor$WorkerThread.run(ProcedureExecutor.java:1741)
{code}
After lots of these, I think I eventually kill'ed the Master and restarted it. 
When it came back, I got all of the corrupt pv2 wal errors:
{noformat}
2018-04-12 22:05:24,050 INFO  
[master/ctr-e138-1518143905142-221855-01-000002:16000] util.FSHDFSUtils: 
Recover lease on dfs file 
hdfs://ctr-e138-1518143905142-221855-01-000002.hwx.site:8020/user/hbase/data/MasterProcWALs/pv2-00000000000000000008.log
2018-04-12 22:05:24,054 INFO  
[master/ctr-e138-1518143905142-221855-01-000002:16000] util.FSHDFSUtils: 
Recovered lease, attempt=0 on 
file=hdfs://ctr-e138-1518143905142-221855-01-000002.hwx.site:8020/user/hbase/data/MasterProcWALs/pv2-00000000000000000008.log
 after 3ms
2018-04-12 22:05:24,103 INFO  
[master/ctr-e138-1518143905142-221855-01-000002:16000] 
procedure2.ProcedureExecutor: Recovered WALProcedureStore lease in 55msec
2018-04-12 22:05:24,431 ERROR 
[master/ctr-e138-1518143905142-221855-01-000002:16000] 
procedure2.ProcedureExecutor: Corrupt pid=3580, ppid=3534, 
state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=TestTable, 
region=71fefffe6b5b3cf1cb6d3328a5a58690
2018-04-12 22:05:24,431 ERROR 
[master/ctr-e138-1518143905142-221855-01-000002:16000] 
procedure2.ProcedureExecutor: Corrupt pid=3586, ppid=3534, 
state=RUNNABLE:REGION_TRANSITION_QUEUE; AssignProcedure table=TestTable, 
region=0e5c6da974e1d3753ba0cb6a8f0db5b1
2018-04-12 22:05:24,431 ERROR 
[master/ctr-e138-1518143905142-221855-01-000002:16000] 
procedure2.ProcedureExecutor: Corrupt pid=3593, ppid=3534, 
state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=TestTable, 
region=f19fbb2563464bcafd528eeba863c10f
2018-04-12 22:05:24,431 ERROR 
[master/ctr-e138-1518143905142-221855-01-000002:16000] 
procedure2.ProcedureExecutor: Corrupt pid=3592, ppid=3534, 
state=RUNNABLE:REGION_TRANSITION_DISPATCH; AssignProcedure table=TestTable, 
region=7df42ee12cc6ff354144e7915e6f0c5a
{noformat}
Will attach the relevant master log. I have ITBLL running now, but will try to 
reproduce these steps and see if I can get something reliably happening.

> [AMv2] Corrupt Procedure WAL file; procedure data stored out of order
> ---------------------------------------------------------------------
>
>                 Key: HBASE-18152
>                 URL: https://issues.apache.org/jira/browse/HBASE-18152
>             Project: HBase
>          Issue Type: Bug
>          Components: Region Assignment
>    Affects Versions: 2.0.0
>            Reporter: stack
>            Assignee: stack
>            Priority: Critical
>             Fix For: 2.0.0
>
>         Attachments: HBASE-18152.master.001.patch, 
> pv2-00000000000000000036.log, pv2-00000000000000000047.log, 
> reading_bad_wal.patch
>
>
> I've seen corruption from time-to-time testing.  Its rare enough. Often we 
> can get over it but sometimes we can't. It took me a while to capture an 
> instance of corruption. Turns out we are write to the WAL out-of-order which 
> undoes a basic tenet; that WAL content is ordered in line w/ execution.
> Below I'll post a corrupt WAL.
> Looking at the write-side, there is a lot going on. I'm not clear on how we 
> could write out of order. Will try and get more insight. Meantime parking 
> this issue here to fill data into.



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)

Reply via email to