最近遇到一個(gè)使用hbck -repair修復(fù)HBase元數(shù)據(jù)遇到的坑，被坑得不清，周末都沒(méi)休息好，時(shí)間全花在給hbck填坑了。今天抽時(shí)間在測(cè)試環(huán)境重現(xiàn)了這個(gè)bug，總算把整個(gè)流程搞明白了，記錄下來(lái)，分享給技術(shù)的朋友們。
詳細(xì)的排查過(guò)程如下：
一、問(wèn)題出現(xiàn)
最近備集群春節(jié)后縮容下架大量的機(jī)器，由于緩存問(wèn)題導(dǎo)致集群不穩(wěn)定（這個(gè)問(wèn)題后面會(huì)專(zhuān)門(mén)寫(xiě)文章來(lái)分析），因此在22號(hào)凌晨的時(shí)候?qū)浞菁鹤隽酥貑?，重啟后集群正常。但是第二天，備集群管理的同事反饋說(shuō)接口成功率比較低，日志反饋是有region沒(méi)上線引起，95c85b3886f19a0637a3b8b7749755e1 not deployed on any region server
負(fù)責(zé)的同事使用如下hbase shell命令進(jìn)行上線操作：
assign '95c85b3886f19a0637a3b8b7749755e1'
但是無(wú)法上線成功，于是聯(lián)系我上來(lái)一起跟進(jìn)。
二、開(kāi)始排查
1、首先查看master的日志，看看有什么報(bào)錯(cuò)信息
具體信息如下日志所示：
master.HMaster: Client=hbaseadmin//ip_address1 assign tablename1_201707,745,1553316101646.95c85b3886f19a0637a3b8b7749755e1.
master.AssignmentManager: Force region state offline {95c85b3886f19a0637a3b8b7749755e1 state=OFFLINE, ts=1553400041143,server=null}
master.AssignmentManager: Assigning tablename1_201707,745,1553316101646.95c85b3886f19a0637a3b8b7749755e1. to 9.7.155.40,60020,1553187654611
2019-03-24 12:00:41,146 INFO [FifoRpcScheduler.handler1-thread-80] master.RegionStates: Transition {95c85b3886f19a0637a3b8b7749755e1 state=OFFLINE, ts=1553400041144, server=null} to {95c85b3886f19a06
37a3b8b7749755e1 state=PENDING_OPEN, ts=1553400041146, server=9ip_address2,60020,1553187654611}
.......此處省略1000個(gè)字
zookeeper.ZKAssign: master:60000-0x162d87d74bf0b8a, quorum=cft-history-db-ss-hbase-zk-4:2181,cft-history-db-ss-hbase-zk-3:2181,cft-history-db-ss
-hbase-zk-2:2181,cft-history-db-ss-hbase-zk-1:2181,cft-history-db-ss-hbase-zk-5:2181, baseZNode=/hbase_cft_history_db_ss Creating (or updating) unassigned node 95c85b3886f19a0637a3b8b7749755e1 with OFFLINE state
從上面的日志中可以看出，這個(gè)region嘗試在9ip_address2這臺(tái)regionserver上進(jìn)行上線操作，但是不成功，后面這個(gè)region又嘗試在多臺(tái)機(jī)器上嘗試上線，均失敗了。從這些日志中無(wú)法快速定位出region無(wú)法上線的原因。
2、查看regionserver的日志找到region不能上線的直接原因
繼續(xù)查看9ip_address2這臺(tái)regionserver的日志，發(fā)現(xiàn)了region不能上線的原因，具體日志如下：
ERROR [RS_OPEN_REGION-ip_address4:60020-6] regionserver.HRegion: Could not initialize all stores for the region=tablename1_201707,745,1553316101646.95c85b3886f19a0637a3b8b7749755e1.
ERROR [RS_OPEN_REGION-ip_address4:60020-6] handler.OpenRegionHandler: Failed open of region=tablename1_201707,745,1553316101646.95c85b3886f19a0637a3b8b7749755e1., starting to roll back the global memstore size.
java.io.IOException: java.io.IOException: java.io.FileNotFoundException: File does not exist: /hbase/data/default/tablename1_201707/7c89f0da4b54a4cc168fe2284e276bb3/i/0a0bed4104a24af280c69e6b67b9501c_SeqId_2_
從上面日志可以看出，95c85b3886f19a0637a3b8b7749755e1上線的時(shí)候會(huì)去讀取7c89f0da4b54a4cc168fe2284e276bb3下面的0a0bed4104a24af280c69e6b67b9501c_SeqId_2_這個(gè)hfile文件，而這個(gè)文件不存在，導(dǎo)致失敗。
在HBase中，一般是region有做分裂后，又還沒(méi)來(lái)得及做major_compact，導(dǎo)致子region中存在指向鏈接文件，這樣才會(huì)去讀取另外一個(gè)region的信息，使用hdfs命令直接查看該region下面的HFile文件，證實(shí)猜想是正確的，如下文件列表所示：
/hbase/data/default/tablename1_201707/95c85b3886f19a0637a3b8b7749755e1/i/0a0bed4104a24af280c69e6b67b9501c_SeqId_2_
/hbase/data/default/tablename1_201707/95c85b3886f19a0637a3b8b7749755e1/i/0a0bed4104a24af280c69e6b67b9501c_SeqId_2_.7c89f0da4b54a4cc168fe2284e276bb3
這個(gè)就是鏈接文件了
備注：為了控制篇幅，這里只顯示兩個(gè)相關(guān)的文件，并把文件的權(quán)限、屬組和屬主都去掉了，另外把IP和表名相關(guān)信息也替換掉了。
但是這又著實(shí)很奇怪，region分裂后，子region的鏈接文件的命名規(guī)則如下：
但是，仔細(xì)看上面的HFile的鏈接文件和文件就會(huì)發(fā)現(xiàn)，鏈接文件的前半部分的父region的文件名和本Region的文件名一模一樣。這太奇怪了，正常是不可能文件名一模一樣的。
3、跟蹤父region的變動(dòng)情況
于是，繼續(xù)通過(guò)查看master日志跟蹤7c89f0da4b54a4cc168fe2284e276bb3這個(gè)父region的相關(guān)分裂日志，如下：
Handled SPLIT event; parent=tablename1_201707,745,1498621284887.7c89f0da4b54a4cc168fe2284e276bb3., daughter a=tablename1_201707,745,1552927092514.ad1d42c37c6f13d9bccc9944fd8740ea., daughter b=tablename1_201707,745498567#2017-07-2710:00:17#1991763146,1552927092514.c35511f97dccac11ea9de6aebf467cb4., on 9.7.157.9,60020,1534514346802
從日志中可以看出，7c89f0da4b54a4cc168fe2284e276bb3通過(guò)split操作分裂為了ad1d42c37c6f13d9bccc9944fd8740ea和c35511f97dccac11ea9de6aebf467cb4兩個(gè)region，根本就沒(méi)有95c85b3886f19a0637a3b8b7749755e1什么事。繼續(xù)查看日志，發(fā)現(xiàn)如下異常日志：
master.HMaster: Client=hbaseadmin//ip_address3 offline tablename1_201707,745,1498621284887.7c89f0da4b54a4cc168fe2284e276bb3.
#本來(lái)是下線狀態(tài)的母region又被下線了一次
master.CatalogJanitor: Daughter region does not exist: ad1d42c37c6f13d9bccc9944fd8740ea, parent is: 7c89f0da4b54a4cc168fe2284e276bb3
#子region不知道被清理掉了
regionserver.HRegionFileSystem: Trying to open a region that do not exists on disk: hdfs://hbase-ns-cft-history-db-ss/hbase/data/default/tablename1_201707/c35511f97dccac11ea9de6aebf467cb4
master.CatalogJanitor: Daughter region does not exist: c35511f97dccac11ea9de6aebf467cb4, parent is: 7c89f0da4b54a4cc168fe2284e276bb3
#另一個(gè)子region也不知道被清理掉了
master.CatalogJanitor: Deleting region tablename1_201707,745,1498621284887.7c89f0da4b54a4cc168fe2284e276bb3. because daughter splits no longer hold references
Region directory (hdfs://cluster1/hbase/data/default/tablename1_201707/7c89f0da4b54a4cc168fe2284e276bb3) was empty, just deleting and returning!
catalog.MetaEditor: Deleted tablename1_201707,745,1498621284887.7c89f0da4b54a4cc168fe2284e276bb3.
#master檢查到母region上沒(méi)有任何的鏈接文件后，直接清理掉了。
備注：這里日志去掉了時(shí)間和部分信息，只保留了核心的日志！
從上面日志看出7c89f0da4b54a4cc168fe2284e276bb3被來(lái)自ip_address3的IP強(qiáng)行下線，并且master發(fā)現(xiàn)這個(gè)region的兩個(gè)子region的文件也不見(jiàn)了。master發(fā)現(xiàn)母region沒(méi)有了引用鏈接后，也被清理掉了。因此前面95c85b3886f19a0637a3b8b7749755e1去讀取鏈接中指向的母region的HFile文件不存在，導(dǎo)致region上線異常。
三、排查和解決問(wèn)題
此時(shí)，有點(diǎn)一頭霧水，但是有個(gè)關(guān)鍵的點(diǎn)是c89f0da4b54a4cc168fe2284e276bb3是直接被ip_address3這個(gè)IP的客戶端下線的，一定是有什么操作觸發(fā)了異常的操作。于是找管理備集群的同事確認(rèn)，集群管理的同事反饋沒(méi)有執(zhí)行任何下線的操作，只是執(zhí)行了hbck -repair操作，-repair 打開(kāi)所有的修復(fù)選項(xiàng)，相當(dāng)于-fixAssignments -fixMeta -fixHdfsHoles -fixHdfsOrphans -fixHdfsOverlaps -fixVersionFile -sidelineBigOverlaps。初步懷疑是hbck執(zhí)行repair的時(shí)候做了“壞事”。
想快速修復(fù)線上問(wèn)題，想首先確認(rèn)一下95c85b3886f19a0637a3b8b7749755e1這個(gè)region是什么時(shí)候創(chuàng)建的，搜索了master的日志，發(fā)現(xiàn)沒(méi)有任何的記錄。繼續(xù)觀察95c85b3886f19a0637a3b8b7749755e1這個(gè)region中的文件，由于鏈接文件和region中的HFile文件名稱相同，并且HFile文件創(chuàng)建的時(shí)候還是2017年的，想到一個(gè)快速上線region的思路。
本來(lái)Region的鏈接文件就是去讀取這個(gè)文件，這個(gè)文件在自己的region下面，那就不需要通過(guò)鏈接文件去讀取了。因此解決辦法就是講鏈接文件移走，在上線即可，操作如下：
hadoop fs -mv link_filename backupdir
assign 'regionname'
操作完成后，接口成功率就上去了：
至此，問(wèn)題得到解決，但是還是有三個(gè)地方有疑惑：
1、95c85b3886f19a0637a3b8b7749755e1是什么時(shí)候創(chuàng)建的？（初步懷疑是hbck搞的鬼，待驗(yàn)證）
2、95c85b3886f19a0637a3b8b7749755e1上的HFile文件是怎么來(lái)的？（初步猜想是hbck從其他三個(gè)region拷貝過(guò)來(lái)的）
3、為什么hbck會(huì)去下線正常的子region？
這些如果能找到hbck -repair的日志也能確定具體hbck干了什么“壞事”，可惜集群管理的同事使用的是命令>號(hào)直接覆蓋掉了日志，導(dǎo)致無(wú)法確定具體的原因。因此只能通過(guò)測(cè)試環(huán)境來(lái)重現(xiàn)該問(wèn)題。
四、測(cè)試重現(xiàn)，找到罪魁禍?zhǔn)?/h1>
通過(guò)之前的排查，發(fā)現(xiàn)幾個(gè)表都是數(shù)據(jù)量比較大，分裂后，還沒(méi)做完major_compact，使用hbck -repair操作會(huì)觸發(fā)類(lèi)型的問(wèn)題。因此在測(cè)試環(huán)境構(gòu)造對(duì)應(yīng)環(huán)境，我的測(cè)試環(huán)境有兩個(gè)region，如下截圖所示：
重現(xiàn)步驟如下：
1、對(duì)第一個(gè)region進(jìn)行split操作，操作命令如下：
split 'fb1c59eb558dcae821e7409a81642b02'
2、分裂成功并且子region上線成功，日志如下：
SPLIT event; parent=table_name2_2015,,1553513856271.fb1c59eb558dcae821e7409a81642b02., daughter a=table_name2_2015,,1553514657067.54c8d09ca7d5fa3ee549cebf118045f5.daughter b=table_name2_2015,34992944,1553514657067.b32e72a1179edb587c9768621f54bb2e., on datanode3,60020,1552573473932
從上面的日志可以看出fb1c59eb558dcae821e7409a81642b02成功分裂為了54c8d09ca7d5fa3ee549cebf118045f5和b32e72a1179edb587c9768621f54bb2e這兩個(gè)region，并且在datanode3,60020,1552573473932這個(gè)regionserver上上線成功餓了。
3、趁還沒(méi)做major_compact的時(shí)候發(fā)起hbck -repair的操作，命令如下:
hbck -repair? >>repair.log 2>&1
4、查看master的日志，看看異常情況，發(fā)現(xiàn)確實(shí)是hbck把三個(gè)region都下線了，日志如下所示：
Client=hbaseadmin//ip_addr5 offline table_name2_2015,,1553514657067.54c8d09ca7d5fa3ee549cebf118045f5.
Transition {54c8d09ca7d5fa3ee549cebf118045f5 state=OPEN, ts=1553514722000,server=datanode3,60020,1553514716244} to {54c8d09ca7d5fa3ee549cebf118045f5 state=OFFLINE, ts=1553514763802, server=datanode3,60020,1553514716244}
Client=hbaseadmin//ip_addr5 offline table_name2_2015,,1553513856271.fb1c59eb558dcae821e7409a81642b02.
Transition {fb1c59eb558dcae821e7409a81642b02 state=SPLIT, ts=1553514721575, server=null} to {fb1c59eb558dcae821e7409a81642b02 state=OFFLINE, ts=1553514763815, server=null}
Client=hbaseadmin//ip_addr5 offline table_name2_2015,34992944,1553514657067.b32e72a1179edb587c9768621f54bb2e.
Transition {b32e72a1179edb587c9768621f54bb2e state=OPEN,ts=1553514722034,server=datanode3,60020,1553514716244} to {b32e72a1179edb587c9768621f54bb2e state=OFFLINE, ts=1553514764826, server=datanode3,60020,1553514716244}
備注：這里對(duì)日志做了下優(yōu)化，去掉了時(shí)間和部分內(nèi)容，只保留核心內(nèi)容
5、此時(shí)頁(yè)面上也由原來(lái)的3個(gè)region變成了孤零零的1個(gè)region，如下圖所示：
6、再分析hbck -repair的日志，終于發(fā)現(xiàn)hbck干的“壞事”了，具體日志如下：
ERROR: (region table_name2_2015,,1553514657067.54c8d09ca7d5fa3ee549cebf118045f5.) Multiple regions have the same startkey:
ERROR: (region table_name2_2015,,1553513856271.fb1c59eb558dcae821e7409a81642b02.) Multiple regions have the same startkey:
ERROR: (regions table_name2_2015,,1553513856271.fb1c59eb558dcae821e7409a81642b02. and table_name2_2015,34992944,1553514657067.b32e72a1179edb587c9768621f54bb2e.) There is an overlap in the region chain.
#執(zhí)行merge region的操作，景三個(gè)region合并成一個(gè)region
util.HBaseFsck: == [hbasefsck-pool1-t26] Merging regions into one region: { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5, deployed =>replicaId => 0 },{meta=>null,hdfs=>hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02, deployed => , replicaId => 0 },{ meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e, deployed => , replicaId => 0 }
#下線三個(gè)region
[hbasefsck-pool1-t26] Offlining region: { meta => null, hdfs =>hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5, deployed => , replicaId => 0 }
util.HBaseFsck: [hbasefsck-pool1-t26] Offlining region: { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02, deployed => , replicaId => 0 }
util.HBaseFsck: [hbasefsck-pool1-t26] Offlining region: { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e, deployed => , replicaId => 0 }
#創(chuàng)建了一個(gè)新region
Created new empty container region: {ENCODED => ed8942007ba8404039022851cc77db6a, NAME => 'table_name2_2015,,1553514764826.ed8942007ba8404039022851cc77db6a.', STARTKEY => '', ENDKEY => '700'} to contain regions: { meta => null, hdfs =>hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5, deployed => , replicaId => 0 },{ meta => null, hdfs =>hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02, deployed => , replicaId => 0 },{ meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e, deployed => , replicaId => 0 }
[hbasefsck-pool1-t26] Merging { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5, deployed => , replicaId => 0 } into hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a
#將三個(gè)region的HFile文件move到新的region目錄下
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5/.tmp into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/.tmp
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5/i into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/i
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5/recovered.edits into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/recovered.edits
util.HBaseFsck: Sidelining files from hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5/.tmp into containing region hdfs://slave:9000/hbase/.hbck/hbase-1553514761533/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5/.tmp
util.HBaseFsck: Removing old region dir: hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5
util.HBaseFsck: [hbasefsck-pool1-t26] Sidelined region dir hdfs://slave:9000/hbase/data/default/table_name2_2015/54c8d09ca7d5fa3ee549cebf118045f5 into hdfs://slave:9000/hbase/.hbck/hbase-1553514761533
util.HBaseFsck: [hbasefsck-pool1-t26] Merging { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02, deployed => , replicaId => 0 } into hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02/.splits into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/.splits
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02/.tmp into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/.tmp
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02/i into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/i
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02/recovered.edits into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/recovered.edits
util.HBaseFsck: Removing old region dir: hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02
util.HBaseFsck: [hbasefsck-pool1-t26] Sidelined region dir hdfs://slave:9000/hbase/data/default/table_name2_2015/fb1c59eb558dcae821e7409a81642b02 into hdfs://slave:9000/hbase/.hbck/hbase-1553514761533
util.HBaseFsck: [hbasefsck-pool1-t26] Merging { meta => null, hdfs => hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e, deployed => , replicaId => 0 } into hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e/.tmp into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/.tmp
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e/i into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/i
util.HBaseFsck: [hbasefsck-pool1-t26] Moving files from hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e/recovered.edits into containing region hdfs://slave:9000/hbase/data/default/table_name2_2015/ed8942007ba8404039022851cc77db6a/recovered.edits
util.HBaseFsck: Removing old region dir: hdfs://slave:9000/hbase/data/default/table_name2_2015/b32e72a1179edb587c9768621f54bb2e
INFO [main] util.HBaseFsck: Loading HBase regioninfo from HDFS...
至此，我們有已經(jīng)知道了hbck -repair干的壞事和我們之前猜測(cè)的差不多，主要問(wèn)題是hbck在修復(fù)的時(shí)候?qū)σ呀?jīng)split的region但是還沒(méi)有來(lái)得及做大合并的region判斷有問(wèn)題，會(huì)將三個(gè)region（1個(gè)母region和2個(gè)子region）進(jìn)行下線，新創(chuàng)建一個(gè)region，并把三個(gè)region涉及到的所有文件都移動(dòng)到新的region中，不會(huì)導(dǎo)致數(shù)據(jù)的丟失，但是會(huì)導(dǎo)致region無(wú)法上線，影響業(yè)務(wù)。
五、代碼分析
稍后再補(bǔ)充
備注：hbase 0.98 和 hbase 1.26都有此問(wèn)題
