现象:
今天部署机架感知,重启standby节点,然后切主生效。在切主的时候使用ambari的 restart zkfc,导致切主不成功并且原standby nn节点挂掉。慌的一匹,问了领导再重启一次就好了,顺便给我讲了一下原理。本着对问题刨根问底的精神,我挖了挖源码,来看看这个问题产生的原因。
首先总结一下导致这个现象的基本原因: restart zkfc的过程很快,大概只有5秒。当Active NN上面的zkfc停掉的时候,被standby NN上的zkfc检测到。于是ZKFC开始准备让standby NN变成Active NN。但是由于这中间需要tail editlog,加载editlog等等耗时的工作,所以肯定是大于5秒的。然后ANN上面的ZKFC重启成功了,检测到对方的状态有问题,又将自己变成ANN。然后当SNN准备变成ANN时,发现自己的epoch小于当前最新的epoch,无法写editlog到journal node,于是抛异常挂掉。
从源码的角度分析
- 准备工作:
收集Namenode挂掉时候的日志:发现有如下内容:
Remote journal [ip地址] failed to write txns 3098267305-3098267305. Will try to write to this JN again after the next log roll.
org.apache.hadoop.ipc.RemoteException(java.io.IOException): IPC's epoch 25 is less than the last promised epoch 26 ; journal id: [集群名]
at org.apache.hadoop.hdfs.qjournal.server.Journal.checkRequest(Journal.java:463)
at org.apache.hadoop.hdfs.qjournal.server.Journal.checkWriteRequest(Journal.java:489)
at org.apache.hadoop.hdfs.qjournal.server.Journal.journal(Journal.java:374)
at org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.journal(JournalNodeRpcServer.java:189)
at org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.journal(QJournalProtocolServerSideTranslatorPB.java:162)
at org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:27401)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:524)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1025)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:876)
at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:822)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1730)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2682)
at org.apache.hadoop.ipc.Client.getRpcResponse(Client.java:1497)
at org.apache.hadoop.ipc.Client.call(Client.java:1443)
at org.apache.hadoop.ipc.Client.call(Client.java:1353)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:228)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Invoker.invoke(ProtobufRpcEngine.java:116)
at com.sun.proxy.$Proxy12.journal(Unknown Source)
at org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolTranslatorPB.journal(QJournalProtocolTranslatorPB.java:187)
at org.apache.hadoop.hdfs.qjournal.client.IPCLoggerChannel$7.call(IPCLoggerChannel.java:396)
at org.apache.hadoop.hdfs.qjournal.client.IPCLoggerChannel$7.call(IPCLoggerChannel.java:389)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
根据log去源码中搜索相关线索,找到如下源码信息:
![](https://img.haomeiwen.com/i5679451/e20ad1de4d459171.png)
reqInfo.getEpoch() 此处是25,lastPromisedEpoch此处是26。
看注释抛出的异常,很容易知道,是往journal node上写editlog时出错了。
那我们就得看看lastPromisedEpoch是在什么条件下会被赋值,顺着set方法找,发现这个对象里面的long值存在于一个磁盘上的文件。当journal node第一次被加载或者之后的任何format操作都会从磁盘上重新加载这个文件。经过追踪调用树,发现如下代码会最终让journal node加载这个值。
![](https://img.haomeiwen.com/i5679451/b47e2cc011b32a21.png)
好的,搞明白lastPromisedEpoch是什么时候加载的之后,我们看看,lastPromisedEpoch是什么时候更新的吧。
QuorumJournalManager类下面有个createNewUniqueEpoch,就是更新lastPromisedEpoch的值的。通过方法调用树,我们最终找到transitionToActive方法会调用createNewUniqueEpoch。
![](https://img.haomeiwen.com/i5679451/c17f4f8d445602b6.png)
也就是说,在切主时,会调用createNewUniqueEpoch方法,增加lastPromises的值。
那也就好解释了,由于SNN切主没成功,原ANN先是transitionToStandby。然后再transitionToActive。这样lastPromisedEpoch又+1。然后SNN在状态变为Active的那短暂时间往journal node写edit log失败,遂挂掉。
Notes
反思一下:切主不能restart zkfc,要用stop zkfc,然后观察状态,切成功之后再启动刚才关闭的ZKFC。
网友评论