[
https://issues.apache.org/jira/browse/HBASE-18152?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
stack updated HBASE-18152:
--------------------------
Attachment: pv2-00000000000000000047.log
Here is a bad WAL. If you read it, you'll see the ....
{code}
2017-06-01 15:30:53,933 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_INIT
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
proc_id: 922
submitted_time: 1496302378185
owner: "stack"
state: RUNNABLE
last_update: 1496302378185
state_data:
"F\b\001\022\033\b\001\022\r\n\005hbase\022\004meta\032\000\"\000(\0000\0008\000\"%\n\031ve0524.halxg.cloudera.com\020\200}\030\252\356\304\224\306+"
}
2017-06-01 15:30:54,007 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_UPDATE
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
proc_id: 922
submitted_time: 1496302378185
owner: "stack"
state: RUNNABLE
stack_id: 0
last_update: 1496302378517
state_data:
"F\b\002\022\033\b\001\022\r\n\005hbase\022\004meta\032\000\"\000(\0000\0008\000\"%\n\031ve0524.halxg.cloudera.com\020\200}\030\252\356\304\224\306+"
}
2017-06-01 15:30:54,008 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_UPDATE
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
proc_id: 922
submitted_time: 1496302378185
owner: "stack"
state: RUNNABLE
stack_id: 0
stack_id: 1
last_update: 1496302378685
state_data:
"F\b\002\022\033\b\001\022\r\n\005hbase\022\004meta\032\000\"\000(\0000\0008\000\"%\n\031ve0524.halxg.cloudera.com\020\200}\030\252\356\304\224\306+"
}
2017-06-01 15:30:54,008 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_UPDATE
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
proc_id: 922
submitted_time: 1496302378185
owner: "stack"
state: SUCCESS
stack_id: 0
stack_id: 1
stack_id: 2
last_update: 1496302379893
state_data:
"F\b\003\022\033\b\001\022\r\n\005hbase\022\004meta\032\000\"\000(\0000\0008\000\"%\n\031ve0524.halxg.cloudera.com\020\200}\030\252\356\304\224\306+"
}
....
{code}
The interesting procedure is pid=941. It has a bunch of children. We check the
file to see if we have all we need to continue processing 941 but though all
subprocedures are present, we fail the check. Since we have read all WALs and
we don't have all info, then the procedure is reported as corrupt.
In this case, all the info is present, it is just out of order. The file ends
in two updates that happened BEFORE two updates recorded earlier. Here is one
example....The last entry in the file is:
{code}
2017-06-01 15:30:54,082 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_UPDATE
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
parent_id: 941
proc_id: 968
submitted_time: 1496302661415
owner: "stack"
state: RUNNABLE
stack_id: 17
last_update: 1496302661492
state_data:
"`\b\002\022Z\b\342\351\255\223\306+\022\'\n\adefault\022\034IntegrationTestBigLinkedList\032\020eV\232}\307P\270U6\334\363/Dg\327!\"\020h\000Uz\207\267\215\273\031\245\177\265\355\t\b\032(\0000\0008\000\030\001"
}
{code}
... but an update that happened later in the processing is recorder in the file
earlier.... as
{code}
2017-06-01 15:30:54,078 INFO [main] wal.ProcedureWALFormatReader(152): type:
PROCEDURE_WAL_UPDATE
procedure {
class_name: "org.apache.hadoop.hbase.master.assignment.AssignProcedure"
parent_id: 941
proc_id: 968
submitted_time: 1496302661415
owner: "stack"
state: RUNNABLE
stack_id: 17
stack_id: 20
last_update: 1496302661692
state_data:
"`\b\002\022Z\b\342\351\255\223\306+\022\'\n\adefault\022\034IntegrationTestBigLinkedList\032\020eV\232}\307P\270U6\334\363/Dg\327!\"\020h\000Uz\207\267\215\273\031\245\177\265\355\t\b\032(\0000\0008\000\030\001"
}
{code}
... note how the earlier entry has two stack_ids (a stack_id is added every
time a procedure is updated) and notice that last update times.
> [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: 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
(v6.3.15#6346)
