Hadoop Router上线过程 Cannot get available namenode 问题分析

在说明这个问题之前，梳理一下router内部的工作流程。

router 内部请求转发流程

上图说明如下：

第1步：通过访问的路径找到挂载点对应的NameSpace（NS）

第2步：通过NS，找到对应的NN

第3步：NN的信息存储在缓存中StateStore

第4步：StateStore启动时，会先加载ZK里面的数据，并且开启一个线程，每隔1分钟去ZK获取最新的记录

第5步：在StateStore启动之后，后启动NamenodeHeartbeatService服务，这个服务每个NN 对应一个线程，线程每隔5秒获取一次NN的状态，并且将信息写入ZK。

router上线过程问题回顾

这里只说关键的步骤，详细步骤请看：音乐集群router上线playbook 上线操作步骤。

在我们操作到上线步骤5时，router启动运行正常，大约1分钟后出现如下日志（关键的日志），最终因为No namenodes available under nameservice 导致集群不可用。

2021-03-16 15:52:46,414 [26743] - INFO [Listener at 0.0.0.0/8024:PeriodicService@141] - Starting periodic service NamenodeHeartbeatService hz-cluster11 nn_1_2
2021-03-16 15:52:47,774 [28103] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:52:52,809 [33138] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:52:57,812 [38141] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:02,817 [43146] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:07,820 [48149] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:12,823 [53152] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:17,826 [58155] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:22,830 [63159] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:27,835 [68164] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:32,839 [73168] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:37,843 [78172] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:42,868 [83197] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY
2021-03-16 15:53:45,242 [85571] - ERROR [IPC Server handler 53 on default port 8020:RouterRpcClient@481] - Cannot get available namenode for hz-cluster11 hadoop3898.jd.163.org:8020 error: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,242 [85571] - ERROR [IPC Server handler 168 on default port 8020:RouterRpcClient@481] - Cannot get available namenode for hz-cluster11 hadoop3898.jd.163.org:8020 error: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,249 [85578] - INFO [Socket Reader #1 for port 8020:ServiceAuthorizationManager@140] - Authorization successful for da_music/dev@HADOOP.HZ.NETEASE.COM (auth:TOKEN) for protocol=interface org.apache.hadoop.hdfs.protocol.ClientProtocol
2021-03-16 15:53:45,249 [85578] - INFO [IPC Server handler 168 on default port 8020:Server@3006] - IPC Server handler 168 on default port 8020, call Call#32 Retry#0 org.apache.hadoop.hdfs.protocol.ClientProtocol.getFileInfo from 10.196.70.37:13222: org.apache.hadoop.ipc.RetriableException: org.apache.hadoop.hdfs.server.federation.router.NoNamenodesAvailableException: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,249 [85578] - INFO [IPC Server handler 53 on default port 8020:Server@3006] - IPC Server handler 53 on default port 8020, call Call#32 Retry#0 org.apache.hadoop.hdfs.protocol.ClientProtocol.getFileInfo from 10.196.77.183:55072: org.apache.hadoop.ipc.RetriableException: org.apache.hadoop.hdfs.server.federation.router.NoNamenodesAvailableException: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,253 [85582] - INFO [Socket Reader #1 for port 8020:Server$Connection@2046] - Auth successful for da_music (auth:TOKEN) via hive/hive7.jd.163.org@HADOOP2.HZ.NETEASE.COM (auth:TOKEN)
2021-03-16 15:53:45,253 [85582] - INFO [Socket Reader #1 for port 8020:Server$Connection@2046] - Auth successful for da_music/dev@HADOOP.HZ.NETEASE.COM (auth:KERBEROS)
2021-03-16 15:53:45,253 [85582] - INFO [Socket Reader #1 for port 8020:Server$Connection@2046] - Auth successful for ndir@HADOOP.HZ.NETEASE.COM (auth:KERBEROS)
2021-03-16 15:53:45,254 [85583] - ERROR [IPC Server handler 121 on default port 8020:RouterRpcClient@481] - Cannot get available namenode for hz-cluster11 hadoop3898.jd.163.org:8020 error: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,254 [85583] - INFO [IPC Server handler 121 on default port 8020:Server@3006] - IPC Server handler 121 on default port 8020, call Call#5 Retry#0 org.apache.hadoop.hdfs.protocol.ClientProtocol.getBlockLocations from 10.196.75.224:20064: org.apache.hadoop.ipc.RetriableException: org.apache.hadoop.hdfs.server.federation.router.NoNamenodesAvailableException: No namenodes available under nameservice hz-cluster11
2021-03-16 15:53:45,254 [85583] - INFO [Socket Reader #1 for port 8020:Server$Connection@2046] - Auth successful for da_music/dev@HADOOP.HZ.NETEASE.COM (auth:KERBEROS)
2021-03-16 15:53:45,254 [85583] - ERROR [IPC Server handler 57 on default port 8020:RouterRpcClient@481] - Cannot get available namenode for hz-cluster11 hadoop3898.jd.163.org:8020 error: No namenodes available under nameservice hz-cluster11

2021-03-16 15:53:48,012 [88341] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:53:53,028 [93357] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:53:58,040 [98369] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:03,042 [103371] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:08,051 [108380] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:13,057 [113386] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:18,059 [118388] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:23,062 [123391] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:28,064 [128393] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:33,071 [133400] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:38,123 [138452] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
2021-03-16 15:54:43,142 [143471] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE

为什么会出现这样的日志。我们的先分析一下上图中，stateStore从ZK加载数据到内存的逻辑。

首先我们根据上线过程，展示一下当时zk里的数据：

音乐集群router上线playbook 上线过程 第1步执行完后ZK的数据：

hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3899.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3898.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3899.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3898.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY

在我们执行第5步时，zk 里的数据变成如下，相当于增加了两条：

hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3899.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3898.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE
hadoop3899.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY
hadoop3898.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY

hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE
hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY

Statestore 从ZK加载过程

那上面的数据加载到内存，是怎么保存的？以及保存的格式？ 如下分析：

为了能够真实反映线上环境数据，通过模拟上线过程，来还原当时的情况，我们已经通过测试用例，将上述10条数据写入ZK。现在我们就从ZK加载，看看具体的加载过程：

首先，会把ZK里面的10条记录加载进来，按照 NS-NNid 进行分组，如上所示，然后再按每个小组，进行仲裁，选取里面最合适的一条记录。 最后放到activeRegistrations 里。所以一个NS 有两条NN记录。

记录仲裁选取流程

再看看，针对每个小组，是如何进行仲裁的：

针对这个小组里面的5条记录，按照NN的状态进行分组。ACTIVE状态的 1条。 STANDBY 状态4条。

他的逻辑是看那个状态的数据多，很明显，STANDBY状态的多，并且还要判断他的数量是不是超过总数的一半, 4 大于 5/2的，然后选择这4条里面最近插入ZK的记录：hadoop3568.jd.163.org_8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY

nn_1_2 小组的选取也是这个逻辑

最后选择出来两条记录

上线过程实际的仲裁结果

这个过程了解了，我们再来看看，上面的日志是怎么产生的。

2021-03-16 15:52:47,774 [28103] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_2-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3897.jd.163.org:8023->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-ACTIVE -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_2:hadoop3898.jd.163.org:8020-STANDBY

这是NN的心跳线程产生的，在我们改完router端口8020，并且NN主备切换。心跳线程获取到3898NN的状态为STANDBY，与内存中ACTIVE状态不一致，就会打印，并且会写到ZK。如果一致就不会打印。上面的日志 2021-03-16 15:53:42,868 之前每个5秒打印了一次。后面就没有再打印，

说明心跳线程获取的状态跟内存一致了，说明StateStore 更新线程，已经从ZK加载，并且通过上面的选取逻辑，更新了内存中的状态，后续的心跳结果与内存一致，所以后面没有再打印上面这条日志。

2021-03-16 15:54:43,142 [143471] - INFO [NamenodeHeartbeatService hz-cluster11 nn_1_1-0:MembershipStoreImpl@170] - NN registration state has changed: hadoop3568.jd.163.org:8023->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-STANDBY -> hadoop3897.jd.163.org:8020->hz-cluster11:nn_1_1:hadoop3897.jd.163.org:8025-ACTIVE

这样的日志一直都有，此时说明内存中的状态一定是这样的：

所以在上面流程图的第2步，会出现这样的日志：

2021-03-16 15:53:45,242 [85571] - ERROR [IPC Server handler 53 on default port 8020:RouterRpcClient@481] - Cannot get available namenode for hz-cluster11 hadoop3898.jd.163.org:8020 error: No namenodes available under nameservice hz-cluster11

这个日志，是在判断，内存的有没有ACTIVE的NN，如果没有，重试后，还是没有ACTIVE的，就会打印上面的日志。

为什么会出现这种情况

通过反推， 我们知道在仲裁 nn_1_2 的时候，ZK只能有一条active 状态的数据。

如果有2条以上，最终的仲裁结果都会是active（2 > 3/2），而不是standby。而且这个内存（activeRegistrations）里面的数据，只有在两种情况会进行修改，一种是在router内部访问hdfs的客户端重试备节点后，如果正常访问，会把statndy状态改为active，并不会由 active → standby。所以这种情况是不可能把它改成statnby状态。而另外一种就是通过

这个每隔一分钟更新的线程来进行修改。而这个仲裁的过程，只能是ZK里面只有一条active状态, 按照我们上线的步骤，这里面是会写入4条端口8023的router，nn_1_2状态 ACTIVE的。

所以这边只能怀疑当时ZK存在数据丢失，这里有3条nn_1_2状态 ACTIVE的记录没有写入，才会出现上述的现象。 回想当初上线过程，ZK 有异常日志，并且修改配置，重启了。

通过在本地模拟,模拟ZK丢失3条nn_1_2状态 ACTIVE的记录，也能复现当时状态更新的日志：

演练结果

演练过程，我们也观察到，NN registration state has changed 相关的日志，但是active 与standby状态 改变的日志都有会打印，说明内存中nn状态的数据与nn心跳的不符，仲裁的结果包含一条active 与standby记录，虽然记录与实际的是相反的，但是通过routerClient重试，也能找到active状态的nn，并更新内存中的状态，所以演练的结果也是没有问题的，后续陆续启动其他的router，最后通过仲裁，nn的状态与实际一致，也不会有这个问题。

解决办法

按照我们上线的逻辑，虽然ZK里面的数据仲裁的结果与实际不符，但是通过重试，也能更新NN的状态，所以也不会有问题，与灰度演练的结果一致。上面这种情况是比较倒霉，ZK出现问题导致active的3条数据未正常写入，才会导致这种情况发生。

后续在上线过程中，可以删除多余的数据，只保留任意一条 ACTIVE 和 一条 STANDBY状态的数据