记一次HDFS Nameserver 死掉原因

柔情只为你懂 2022-10-01 15:56 130阅读 0赞

[2019独角兽企业重金招聘Python工程师标准>>> ][2019_Python_] ![hot3.png][]

在测试环境部署了ambari hdp集群，hdfs 2.7nameserver做了高可用journal +zkfailover实现，偶遇一次nameserver自己死掉，没有自动恢复，查找原因：

nameserver死亡最后日志：  
2018-10-17 02:02:05,981 FATAL namenode.FSEditLog (JournalSet.java:mapJournalsAndReportErrors(398)) - Error: flush failed for required journal (JournalAndStream(mgr=QJM to \[10.213.33.71:8485, 10.213.33.72:8485, 10.213.33.70:8485\], stream=QuorumOutputStream starting at txid 15384179))  
java.io.IOException: Timed out waiting 20000ms for a quorum of nodes to respond.  
at org.apache.hadoop.hdfs.qjournal.client.AsyncLoggerSet.waitForWriteQuorum(AsyncLoggerSet.java:137)  
at org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.flushAndSync(QuorumOutputStream.java:107)  
at org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:113)  
at org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:107)  
at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalSetOutputStream$8.apply(JournalSet.java:533)  
at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393)  
at org.apache.hadoop.hdfs.server.namenode.JournalSet.access$100(JournalSet.java:57)  
at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalSetOutputStream.flush(JournalSet.java:529)  
at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:707)  
at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:641)  
at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.mkdirs(FSNamesystem.java:4192)  
at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.mkdirs(NameNodeRpcServer.java:1109)  
at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.mkdirs(ClientNamenodeProtocolServerSideTranslatorPB.java:645)  
at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)  
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:640)  
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:982)  
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2351)  
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2347)  
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:1869)  
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2347)  
2018-10-17 02:02:05,982 WARN client.QuorumJournalManager (QuorumOutputStream.java:abort(72)) - Aborting QuorumOutputStream starting at txid 15384179

表面原因是nameserver向journalnode写editlog的时候超时，自己关闭；进一步查找journal超时原因:  
2018-10-17 01:37:04,312 INFO ipc.Server (Server.java:logException(2435)) - IPC Server handler 2 on 8485, call org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocol.journal from 10.213.33.71:47256 Call\#1181544 Retry\#0  
java.io.IOException: IPC's epoch 16 is less than the last promised epoch 17  
at org.apache.hadoop.hdfs.qjournal.server.Journal.checkRequest(Journal.java:430)  
at org.apache.hadoop.hdfs.qjournal.server.Journal.checkWriteRequest(Journal.java:456)  
at org.apache.hadoop.hdfs.qjournal.server.Journal.journal(Journal.java:351)  
at org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.journal(JournalNodeRpcServer.java:153)  
at org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.journal(QJournalProtocolServerSideTranslatorPB.java:158)  
at org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:25421)  
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:640)  
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:982)  
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2351)  
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2347)  
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:1869)  
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2347)  
2018-10-17 01:37:04,454 INFO namenode.TransferFsImage (TransferFsImage.java:copyFileToStream(395)) - Sending fileName: /hadoop/hdfs/journal/NN1/current/edits\_0000000000015383967-0000000000015384178, fileSize: 27886. Sent total: 27886 bytes. Size of last segment intended to send: -1 bytes.  
2018-10-17 01:58:36,681 WARN server.Journal (Journal.java:journal(398)) - Sync of transaction range 15389759-15389759 took 6360ms  
2018-10-17 02:00:34,791 WARN server.Journal (Journal.java:journal(398)) - Sync of transaction range 15390699-15390699 took 6783ms  
2018-10-17 02:02:04,867 WARN server.Journal (Journal.java:journal(398)) - Sync of transaction range 15391171-15391171 took 18885ms  
分析日志得出：发生了nameserver的主备切换（主nameserver不能连接zk，zk重启了，原因后面再查找），导致了新的主nameserver恢复后写journal信息时，journal服务发现nameserver上送过来的epoch时间戳落后于当前他自己的epoch时间戳，于是发起同步流程，nameserverjournalnode节点同步，同步过程花费18.885s，导致对外服务等待超时

018-10-17 02:02:04,191 - WARN \[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn[@362][362]\] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running  
2018-10-17 02:02:04,191 - INFO \[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn[@1033][1033]\] - Closed socket connection for client /10.213.33.71:36564 (no session established for client)  
2018-10-17 02:02:04,765 - INFO \[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory[@197][197]\] - Accepted socket connection from /10.213.33.70:38640  
2018-10-17 02:02:04,765 - WARN \[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn[@362][362]\] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running  
2018-10-17 02:02:04,765 - INFO \[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn[@1033][1033]\] - Closed socket connection for client /10.213.33.70:38640 (no session established for client)  
2018-10-17 02:02:04,867 - WARN \[SyncThread:1:FileTxnLog@334\] - fsync-ing the write ahead log in SyncThread:1 took 24133ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide  
2018-10-17 02:02:04,868 - WARN \[SyncThread:1:SendAckRequestProcessor@64\] - Closing connection to leader, exception during packet send  
java.net.SocketException: Socket closed  
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)  
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)  
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)  
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)  
at org.apache.zookeeper.server.quorum.Learner.writePacket(Learner.java:139)  
at org.apache.zookeeper.server.quorum.SendAckRequestProcessor.flush(SendAckRequestProcessor.java:62)  
at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:204)  
at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:131)  
2018-10-17 02:02:04,869 - INFO \[SyncThread:1:SyncRequestProcessor@187\] - SyncRequestProcessor exited!  
2018-10-17 02:02:04,891 - WARN \[QuorumPeer\[myid=1\]/0:0:0:0:0:0:0:0:2181:SendAckRequestProcessor@64\] - Closing connection to leader, exception during packet send  
java.net.SocketException: Socket closed  
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)  
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)  
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)  
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)  
网络不稳定导致zk之间通讯中断，服务不能提供了

解决办法：

1，其实在实际的生产环境中，也很容易发生类似的这种超时情况，所以我们需要把默认的20s超时改成更大的值，比如60s。

我们可以在hadoop/etc/hadoop下的hdfs-site.xml中，加入一组配置:

<property>
            <name>dfs.qjournal.write-txns.timeout.ms</name>
            <value>60000</value>
    </property>

2，把zkfailovercontroller去掉，改为手动切换主备nameserver.

修改参数dfs.ha.automatic-failover.enabled=false

当需要切换主备时，使用Hdfs用户（su hdfs）, 执行命令hdfs haadmin -failover --forcefence --forceactive nn2 nn1  
切换之前同步主备的fsimage和editlog

转载于:https://my.oschina.net/u/3522232/blog/2248661

[2019_Python_]: https://my.oschina.net/u/2663968/blog/3061697
[hot3.png]: /images/20220113/19e0f77f1cb94e978f57d2d4018f26d3.png
[362]: https://my.oschina.net/u/3197762
[1033]: https://my.oschina.net/u/3424716
[197]: https://my.oschina.net/197