Hbase regionserver 逐個掛掉的問題分析

最近遇到一個比較詭異的問題，一個regionserver由于GC的原因，導致與zookeeper鏈接超時，最終被踢出集群。但是，接下來的現象，才是噩夢的開始！！！

1. 一個regionserver由于GC的原因，導致與zookeeper鏈接超時，最終被踢出集群。

~~~Hbase regionserver log~~~
2018-05-31 11:42:17,739 INFO  [MemStoreFlusher.0] regionserver.HRegion: Started memstore flush for cn_kong_groups,\x00\x00\xBB\xE9\x03\x03\x00D\xDF,1527701650816.a177e358544ffe3157a4c0531feb8e5a., current region memstore size 123.40 MB, and 1/1 column families' memstores are being flushed.
2018-05-31 11:42:17,740 WARN  [JvmPauseMonitor] util.JvmPauseMonitor: Detected pause in JVM or host machine (eg GC): pause of approximately 52612ms
GC pool 'ParNew' had collection(s): count=1 time=45897ms
GC pool 'ConcurrentMarkSweep' had collection(s): count=2 time=6814ms
2018-05-31 11:42:17,741 WARN  [B.defaultRpcServer.handler=0,queue=0,port=16020] ipc.RpcServer: (responseTooSlow): {"processingtimems":52721,"call":"Scan(org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ScanRequest)","client":"10.21.23.232:55676","starttimems":1527738085020,"queuetimems":0,"class":"HRegionServer","responsesize":15,"method":"Scan"}
2018-05-31 11:42:17,745 INFO  [regionserver/regionserver1.bigdata.com/172.16.11.66:16020-SendThread(ip-10-21-14-154.bigdata.com:2181)] zookeeper.ClientCnxn: Client session timed out, have not heard from server in 61597ms for sessionid 0x15f3454790276db, closing socket connection and attempting reconnect
2018-05-31 11:42:17,745 INFO  [main-SendThread(ip-10-21-14-154.bigdata.com:2181)] zookeeper.ClientCnxn: Client session timed out, have not heard from server in 61595ms for sessionid 0x15f3454790276da, closing socket connection and attempting reconnect
2018-05-31 11:42:17,893 INFO  [sync.3] wal.FSHLog: Slow sync cost: 148 ms, current pipeline: [DatanodeInfoWithStorage[172.16.11.66:50010,DS-ac448b6f-2964-4900-aeda-4547f2d956b8,DISK], DatanodeInfoWithStorage[172.16.11.67:50010,DS-e8b1727a-81d5-4b65-9854-6b6ad6749b64,DISK], DatanodeInfoWithStorage[10.21.23.41:50010,DS-56eb0e28-5b3c-4047-acc3-d79f3f6bacc2,DISK]]
2018-05-31 11:42:17,893 INFO  [sync.2] wal.FSHLog: Slow sync cost: 150 ms, current pipeline: [DatanodeInfoWithStorage[172.16.11.66:50010,DS-ac448b6f-2964-4900-aeda-4547f2d956b8,DISK], DatanodeInfoWithStorage[172.16.11.67:50010,DS-e8b1727a-81d5-4b65-9854-6b6ad6749b64,DISK], DatanodeInfoWithStorage[10.21.23.41:50010,DS-56eb0e28-5b3c-4047-acc3-d79f3f6bacc2,DISK]]

2. Full GC的問題，拋開先不管，一個詭異的問題出現了，啟動這個regionserver之后，不長時間這個regionserver又掛掉了。而且，陸續有其他regionserver開始掛掉。

2018-05-31 12:20:12,919 ERROR [RS_OPEN_REGION-regionserver1:16020-2] coprocessor.CoprocessorHost: The coprocessor org.apache.dfs.storage.hbase.cube.v1.coprocessor.observer.AggregateRegionObserver threw org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.ipc.StandbyException): Operation category READ is not supported in state standby
        at org.apache.hadoop.hdfs.server.namenode.ha.StandbyState.checkOperation(StandbyState.java:87)
        at org.apache.hadoop.hdfs.server.namenode.NameNode$NameNodeHAContext.checkOperation(NameNode.java:1774)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkOperation(FSNamesystem.java:1313)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:3856)
        at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.getFileInfo(NameNodeRpcServer.java:1006)
        at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.getFileInfo(ClientNamenodeProtocolServerSideTranslatorPB.java:843)
        at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
        at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:616)
        at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:969)
        at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2049)
        at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2045)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:415)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1657)
        at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2043)

2018-05-31 12:20:12,923 ERROR [RS_OPEN_REGION-regionserver1:16020-2] regionserver.HRegionServer: ABORTING region server regionserver1.bigdata.com,16020,1527740222472: The coprocessor org.apache.dfs.storage.hbase.cube.v1.coprocessor.observer.AggregateRegionObserver threw org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.ipc.StandbyException): Operation category READ is not supported in state standby
        at org.apache.hadoop.hdfs.server.namenode.ha.StandbyState.checkOperation(StandbyState.java:87)
        at org.apache.hadoop.hdfs.server.namenode.NameNode$NameNodeHAContext.checkOperation(NameNode.java:1774)
        at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkOperation(FSNamesystem.java:1313)

3. 下面是另一個regionserver的日志，都可以看到"Operation category READ is not supported in state standby"，然后"ABORTING region server"

org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.ipc.StandbyException): Operation category READ is not supported in state standby
at org.apache.hadoop.hdfs.server.namenode.ha.StandbyState.checkOperation(StandbyState.java:87)
at org.apache.hadoop.hdfs.server.namenode.NameNode$NameNodeHAContext.checkOperation(NameNode.java:1774)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.checkOperation(FSNamesystem.java:1313)
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getFileInfo(FSNamesystem.java:3856)
at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.getFileInfo(NameNodeRpcServer.java:1006)
at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.getFileInfo(ClientNamenodeProtocolServerSideTranslatorPB.java:843)
at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:616)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:969)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2049)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2045)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1657)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2043)
2018-05-31 12:20:13,678 ERROR [RS_OPEN_REGION-regionserver2:16020-2] regionserver.HRegionServer: ABORTING region server regionserver2.bigdata.com,16020,1519906845598: The coprocessor

4. 為什么會出現這個情況呢？感覺十分詭異。

最后經過查找，并且有老司機的指引，發現了問題點。部分hbase表，使用了coprocessor功能，而這個也不是關鍵

hbase 表的信息如下，注意這部分：hdfs://dfs/dfs/dfs_metadata/coprocessor/*****

dfs_ZZQSWFZ4VW', {TABLE_ATTRIBUTES => 
{coprocessor$1 => 'hdfs://dfs/dfs/dfs_metadata/coprocessor/dfs-coprocessor-1.5.4.1-0.jar|org.apache.dfs.storage.hbase.cube.v2.coprocessor.endpoint.CubeVisitService|1001|', 
coprocessor$2 => 'hdfs://dfs/dfs/dfs_metadata/coprocessor/dfs-coprocessor-1.5.4.1-0.jar|org.apache.dfs.storage.hbase.cube.v1.coprocessor.observer.AggregateRegionObserver|1002|', 
METADATA => {'CREATION_TIME' => '1478338090339', 'GIT_COMMIT' => 'c4e31c1b3a664f598352061ae8703812e9d9cef7;', 'dfs_HOST' => 'dfs_metadata', 'OWNER' => 'xxxx.owner@bigdata.com', 'SEGMENT' => 'WindGreenwichOffline_dev[20161105070130_20161105092132]', 
'SPLIT_POLICY' => 'org.apache.hadoop.hbase.regionserver.DisabledRegionSplitPolicy', 'USER' => 'ADMIN'}}, {NAME => 'F1', DATA_BLOCK_ENCODING => 'FAST_DIFF', BLOOMFILTER => 'NONE', COMPRESSION => 'SNAPPY'}

5. 關鍵點來了，當前的hdfs namenode是HA模式的，但是這個集群，最早是單點namenode的，而當時創建的一些，使用了coprocessor的hbase表，是問題的觸發點。

這些coprocessor，指定了hdfs的訪問名稱，所以，只有原來的namenode是active的狀態，才能正常訪問。一旦active-standby發生切換，這部分表，就無法正常加載與訪問。最終導致整個regionserver的異常。

hbase 表的信息如下，注意這部分：hdfs://old_namenode_host.bigdata.com:9000/dfs/dfs_metadata/*****   這里使用了具體的主機名

'dfs_1KT8V5FL1C', {TABLE_ATTRIBUTES => 
{coprocessor$1 => '|org.apache.hadoop.hbase.security.access.SecureBulkLoadEndpoint|107374663|', 
coprocessor$2 => 'hdfs://old_namenode_host.bigdata.com:9000/dfs/dfs_metadata/coprocessor/dfs-coprocessor-1.5.4.1-1.jar|org.apache.dfs.storage.hbase.cube.v2.coprocessor.endpoint.CubeVisitService|1001|', 
coprocessor$3 => 'hdfs://old_namenode_host.bigdata.com:9000/dfs/dfs_metadata/coprocessor/dfs-coprocessor-1.5.4.1-1.jar|org.apache.dfs.storage.hbase.cube.v1.coprocessor.observer.AggregateRegionObserver|1002|', 
METADATA => {'CREATION_TIME' => '1493632152602', 'GIT_COMMIT' => 'c4e31c1b3a664f598352061ae8703812e9d9cef7;', 'dfs_HOST' => 'dfs_metadata', 'OWNER' => 'xxxx.owner@bigdata.com', 'SEGMENT' => 'WindCGN2_clone[20160501000000_20170501000000]', 
'SPLIT_POLICY' => 'org.apache.hadoop.hbase.regionserver.DisabledRegionSplitPolicy', 'USER' => 'ADMIN'}}, {NAME => 'F1', DATA_BLOCK_ENCODING => 'FAST_DIFF', BLOOMFILTER => 'NONE', COMPRESSION => 'SNAPPY'}

最后總結，為什么會其他的regionserver逐個掛掉呢？為什么namenode已經切換很久，在GC引發regionserver掛掉，才會導致regionserver逐個掛掉的連鎖反應？

1. GC引起第一個regionserver掛掉，而其上的region，一定會被master分配到其他的regionserver上，而其他的regionserver也不能正確接管這個region，所以也是以相同的錯誤，導致第二個regionserver掛掉，然后第三個。理論上，全部的regionserver都會掛掉。

2. 由于在第一個regionserver掛掉前，namenode active-standby發生切換之前，hbase regionserver已經啟動，并且能正常識別region，所以沒有引發問題，但是regionserver發生重啟，就肯定不能正常掛載這個region的。

關于coprocessor功能，請參考

http://www.zhyea.com/2017/04/13/using-hbase-coprocessor.html

https://www.3pillarglobal.com/insights/hbase-coprocessors