解决Namenode异常停止后无法正常启动

背景:

公司在线上使用了CDH5 HA模式,有两个Namenode节点,结果其中的Standby节点因为一些关于edits文件的报错异常停止了,并且在启动的过程中一直报告找不到各种文件。

刚开始怀疑问题可能只发生在Standby本身,因此尝试了bootstrapStandby来重新初始化Standby节点,但问题依旧。
而后来因为我尝试重启ZKFC(Zookeeper Failover)服务器,导致了Active节点进行自动切换,在切换失败后打算切换回去时,也无法启动服务了,报错跟Standby节点一模一样,于是整个Hadoop集群就挂了。

问题严重,在搜遍了整个Google都找不到任何有用的信息之后,只能求助于老大。最后,老大想到一个思路,就是将fsimage(元数据)文件与edits(编辑日志)文件都反编译成文本,查看里面具体有什么内容,为什么加载edits文件时会报错。

结果,这个思路给我们带来了曙光,并最终修复了整个集群。

环境介绍:
idc2-server1: namenode, journalnode, zkfc
idc2-server2: namenode, journalnode, zkfc
idc2-server3: journalnode, resourcemanager

具体过程:
首先,是Standby Namenode上出现以下错误,然后自动异常关闭了进程:

2014-11-11 02:12:54,057 FATAL org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Unknown error encountered while tailing edits. Shutting down standby NN.
java.io.FileNotFoundException: File does not exist: /user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015
       at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:65)
       at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:55)
...
其中提到了"Unknown error encountered while tailing edits. Shutting down standby NN."

于是,我们尝试启动Standby Namenode服务,结果报告以下错误:

2014-11-12 04:26:28,860 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream 'http://idc2-server10.heylinux.com:8480/getJournal?jid=idc2&segmentTxId=240823073&storageInfo=-55%3A1838233660%3A0%3ACID-d77ea84b-1b24-4bc2-ad27-7d2384d222d6' to transaction ID 240741256
2014-11-12 04:26:28,874 ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader: Encountered exception on operation CloseOp [length=0, inodeId=0, path=/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015, replication=3, mtime=1415671845582, atime=1415670522749, blockSize=134217728, blocks=[], permissions=oozie:hdfs:rw-r--r--, aclEntries=null, clientName=, clientMachine=, opCode=OP_CLOSE, txid=240823292]
java.io.FileNotFoundException: File does not exist: /user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:65)
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:55)
...
2014-11-12 04:26:32,641 WARN org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Encountered exception loading fsimage
java.io.FileNotFoundException: File does not exist: /user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:65)
说找不到"/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015"这个文件。
而事实上,这个文件是临时文件,不重要并且已经被删除了。
但在上面,却报告"ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader: Encountered exception on operation CloseOp",可以看出是在加载edits文件,执行OP_CLOSE操作时提示找不到文件。

刚开始我们怀疑可能只是Standby上的fsimage文件或edits文件有问题,于是我们在Standby上执行了bootstrapStandby,改过程会自动从Active Namenode上获取最新的fsimage文件,并从Journalnode日志服务器上下载并执行新的edits文件。

sudo -u hdfs hadoop namenode -bootstrapStandby
但是,在初始化之后,加载edits时仍然遇到上面相同的报错。

而接下来,由于我尝试将ZKFC(Zookeeper Failover)服务重启,导致了Active Namenode自动切换到Standby,但由于Standby无法take over,所以Active Namenode切换回去的时候,也无法正常重启了,错误跟Standby启动时一样。

这样一来,整个Hadoop集群就挂了,在搜遍了整个Google都找不到任何有用的信息之后,我打电话给了老大,老大也通过上面的错误Google不到任何一条有用的信息。
于是老大尝试在edits文件中grep上面的路径,找到了一些相关的edits文件:

# cd /data1/dfs/nn/
# cp -rpa current current.backup.orig
# cd /data2/dfs/nn/
# cp -rpa current current.backup.orig
# cd /data1/dfs/nn/current
# grep attempt_1415171013961_37060_m_000015_0 *
Binary file edits_0000000000240687057-0000000000240698453 matches
Binary file edits_0000000000240823073-0000000000240838096 matches
Binary file edits_inprogress_0000000000244853266 matches
于是,我们思考能否从这些edits文件或fsimage文件中找到一些线索。
而下面的两篇文章中,提到了Hadoop自带的针对fsimage和edits文件的反编译工具:
http://hadoop.apache.org/docs/current/hadoop-project-dist/hadoop-hdfs/HdfsImageViewer.html
http://hadoop.apache.org/docs/current/hadoop-project-dist/hadoop-hdfs/HdfsEditsViewer.html

其中,关于edits文件的一些描述给我们带来了极大的希望:

In case there is some problem with hadoop cluster and the edits file is corrupted it is possible to save at least part of the edits file that is correct. This can be done by converting the binary edits to XML, edit it manually and then convert it back to binary.
通过以上描述,我们了解到edits文件可能会corrupted,而反编译之后手动修改,在编译回二进制格式进行替换,可以作为一种解决办法。
于是我们将上面找到的两个关联edits文件,将其复制出来并进行了反编译:

# mkdir /tmp2/
# cd /data1/dfs/nn
# cp edits_0000000000240687057-0000000000240698453 /tmp2/
# cp edits_0000000000240823073-0000000000240838096 /tmp2/
# cd /tmp2
# hdfs oev -i edits_0000000000240687057-0000000000240698453 -o edits_0000000000240687057-0000000000240698453.xml
# hdfs oev -i edits_0000000000240823073-0000000000240838096 -o edits_0000000000240823073-0000000000240838096.xml
反编译之后,生成了两个XML文件,我们在XML文件中搜索"/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015",找到了OP_CLOSE与OP_DELETE相关记录:

  <RECORD>
    <OPCODE>OP_DELETE</OPCODE>
    <DATA>
      <TXID>240818498</TXID>
      <LENGTH>0</LENGTH>
      <PATH>/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015</PATH>
      <TIMESTAMP>1415671972595</TIMESTAMP>
      <RPC_CLIENTID>4a38861d-3bee-40e6-abb6-d2b58f313781</RPC_CLIENTID>
      <RPC_CALLID>676</RPC_CALLID>
    </DATA>
  </RECORD>
  <RECORD>
    <OPCODE>OP_CLOSE</OPCODE>
    <DATA>
      <TXID>240823292</TXID>
      <LENGTH>0</LENGTH>
      <INODEID>0</INODEID>
      <PATH>/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015</PATH>
      <REPLICATION>3</REPLICATION>
      <MTIME>1415671845582</MTIME>
      <ATIME>1415670522749</ATIME>
      <BLOCKSIZE>134217728</BLOCKSIZE>
      <CLIENT_NAME></CLIENT_NAME>
      <CLIENT_MACHINE></CLIENT_MACHINE>
      <PERMISSION_STATUS>
        <USERNAME>oozie</USERNAME>
        <GROUPNAME>hdfs</GROUPNAME>
        <MODE>420</MODE>
      </PERMISSION_STATUS>
    </DATA>
  </RECORD>
可以看到,对于"/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000015_0/part-00015",OP_DELETE发生在了OP_CLOSE之前,因此执行OP_CLOSE时会提示"File does not exist"。

于是,我们尝试将OP_CLOSE这部分代码,替换成其它的内容,比如无关痛痒的修改一个现有文件的权限,并保留TXID 240823292以确保edits文件的完整性。

  <RECORD>
    <OPCODE>OP_SET_PERMISSIONS</OPCODE>
    <DATA>
      <TXID>240823292</TXID>
      <SRC>/user/oozie-heylinux/.staging/job_1415171013961_37194</SRC>
      <MODE>504</MODE>
    </DATA>
  </RECORD>
修改完成之后,再将XML文件反编译回binary格式。

# cd /tmp2/
# cp edits_0000000000240823073-0000000000240838096.xml edits_0000000000240823073-0000000000240838096.xml.orig
# vim edits_0000000000240823073-0000000000240838096.xml
# hdfs oev -i edits_0000000000240823073-0000000000240838096.xml -o edits_0000000000240823073-0000000000240838096 -p binary
然后将binary文件同步到journalnode日志服务器中:

# cd /var/hadoop/data/dfs/jn/idc2prod/
# cp -rpa current current.backup.orig
# cd /tmp2/
# cp edits_0000000000240823073-0000000000240838096 /data1/dfs/nn/current/
# cp edits_0000000000240823073-0000000000240838096 /data2/dfs/nn/current/
# cp edits_0000000000240823073-0000000000240838096 /var/hadoop/data/dfs/jn/idc2prod/current/
# scp edits_0000000000240823073-0000000000240838096 root@idc2-server2:/var/hadoop/data/dfs/jn/idc2prod/current/
# scp edits_0000000000240823073-0000000000240838096 root@idc2-server3:/var/hadoop/data/dfs/jn/idc2prod/current/
然后启动namenode服务,可以发现,之间的错误已经不存在了,取而代之的已经变成了其它文件。

2014-11-12 08:57:13,053 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream 'http://idc2-server1.heylinux.com:8480/getJournal?jid=idc2prod&segmentTxId=240823073&storageInfo=-55%3A1838233660%3A0%3ACID-d77ea84b-1b24-4bc2-ad27-7d2384d222d6' to transaction ID 240299210
2014-11-12 08:57:13,063 ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader: Encountered exception on operation CloseOp [length=0, inodeId=0, path=/user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000018_0/part-00018, replication=3, mtime=1415671845675, atime=1415670519537, blockSize=134217728, blocks=[], permissions=oozie:hdfs:rw-r--r--, aclEntries=null, clientName=, clientMachine=, opCode=OP_CLOSE, txid=240823337]
java.io.FileNotFoundException: File does not exist: /user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000018_0/part-00018
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:65)
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:55)
...

2014-11-12 08:57:16,847 WARN org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Encountered exception loading fsimage
java.io.FileNotFoundException: File does not exist: /user/dong/data/dpp/classification/gender/vw-output-train/2014-10-30-research-with-confict-fix-bug-rerun/_temporary/1/_temporary/attempt_1415171013961_37060_m_000018_0/part-00018
        at org.apache.hadoop.hdfs.server.namenode.INodeFile.valueOf(INodeFile.java:65)
...
那么,接下来,就是重复以上动作,其中有时候能找到一部分规律,可以批量将同一个目录下反复报错的文件的OP_CLOSE都替换掉。但更多的时候则是随机的文件,需要一次次修改XML文件,然后编译成binary,再启动namenode,进行针对性的修改,一直反复的进行下去,直到Namenode能够成功启动为止。

我们在具体的操作过程中,还遇到过关于OP_ADD_BLOCK的错误,造成问题的原因是由于最后一个edits文件在反编译回binary文件时出现一些关于OP_UPDATE_BLOCK的错误。
我将报错的部分通过以上方式进行了替换,才成功的将edits文件反编译回binary文件。
具体的解决办法,就是根据"Encountered exception on operation AddBlockOp"定位到OP_ADD_BLOCK相关配置并替换即可。

2014-11-12 18:07:39,070 ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader: Encountered exception on operation AddBlockOp [path=/user/dong/data/dpp/classification/gender/vw-input/2014-10-30-research-with-no-confict-fix-bug-rerun/all_labelled/_temporary/1/_temporary/attempt_1415171013961_42350_m_001474_0/part-m-01474, penultimateBlock=NULL, lastBlock=blk_1109647729_35920089, RpcClientId=, RpcCallId=-2]
java.lang.IllegalStateException
最后,在Namenode启动成功后,会报告很多Block丢失,解决办法是通过fsck删除这些错误的Block。

# hadoop fsck / -files -blocks -locations | tee -a fsck.out
然后在fsck.out中获取所有Block的信息,执行"hadoop fsck / -move"加Block路径进行删除。

最后,退出safemode,生活再次变得美好起来。

# hadoop dfsadmin -safemode leave
PS: 在后来,上面的问题又再次出现了,通过分析我们发现是由于Hadoop的一个Bug导致的,从2.10-beta就开始存在了:
https://issues.apache.org/jira/browse/HDFS-6527
https://issues.apache.org/jira/browse/HDFS-6647
想要彻底避免这类问题的再次发生,必须将Hadoop升级到2.5以上版本,而对应的CDH版本则是5.2.0

时间: 2024-10-31 17:28:45

解决Namenode异常停止后无法正常启动的相关文章

五条命令轻松解决安装Win7系统后XP无法启动故障

  在测试的时候,测试机原本就安装有xp系统,因为不想破坏原有的分区结构,所以就挂了一块30G的旧硬盘专门来安装windows7系统,这个硬盘只有一个分区,格式为NTFS,在XP下设置的盘符为W,挂接在IDE口并被设定为从盘. 在硬盘上安装win7系统之后,一切都是正常的,不过引导菜单中却没有xp启动.估计是因为主从硬盘盘符冲突之类的问题造成的. 基于Windows 7与Vista在基本内核上非常接近,所以我们可以利用安装盘下boot目录中的bootsect.exe程序修复引导区,基于同样的假设

MySQL无法启动、无法停止解决方法(安全设置后容易出现)_Mysql

最近在Windows 2003上的MySQL出现过多次正常运行时无法连接数据库故障,现象是无法连接数据库,也无法停止MySQL或重启MYSQL,重启机子也没有效果,由于每次都是草草尝试各种方法搞定即可,一直没有深入研究,下次一定把图和故障现象系统归纳一下.本文先列一下常见的解决方法. 一.确认MYSQL已经配置且正确 重新配置 如果是重新安装的MYSQL,请确认安装后的MYSQL经过第一次配置,否则会缺少my.ini文件,配置方法,可以在安装到最后一步时选择,现在开始配置MYSQL,或在程序组中

【错误解决】本地计算机上的mysql服务启动停止后,某些服务在未由其他服务或程序使用时将自动停止

转载请注明出处http://blog.csdn.net/qq_26525215 本文源自[大学之旅_谙忆的博客] 在启动mysql服务时出现该错误: 本地计算机上的mysql服务启动停止后,某些服务在未由其他服务或程序使用时将自动停止. mysql 版本 5.7.14 系统 win 7 后来经过一系列的百度谷歌总算是解决了. 首先你需要把原来的服务删除 mysqld --remove mysql 注意:mysql为你的服务名称自己可以随便定义的. 此命令需要进入mysql安装目录下的bin目录运

Oracle 9i 数据库异常关闭后的启动_oracle

正在看的ORACLE教程是:Oracle 9i 数据库异常关闭后的启动. Oracle 数据库启动  Oracle shutdown的时候突然断电,导致使用sql/plus启动时无法连接到数据库,具体描述为: connection can not permitted, shut in progress. 到dos 提示符 键入:  c:\> sqlplus /nolog  显示: sql/plus: Realease9.0.2--..all rights reserved sql> conne

Oracle9i数据库异常关闭后的启动_oracle

正在看的ORACLE教程是:Oracle9i数据库异常关闭后的启动.Oracle shutdown的时候突然断电,导致使用sql/plus启动时无法连接到数据库,具体描述为: connection can not permitted, shut in progress. 到dos 提示符 键入: c:\> sqlplus /nolog 显示: sql/plus: Realease9.0.2--..all rights reserved sql> connect /as sysdba 显示已连接

修改计算机名或IP后Oracle10g无法启动服务的解决办法

  修改计算机名或IP后Oracle10g无法启动服务的解决办法 遇到的问题,问题产生原因不详.症状为,windows服务中有一项oracle服务启动不了,报出如下错误. Windows 不能在 本地计算机 启动 OracleDBConsoleorcl .有关更多信息,查阅系统事件日志.如果这是非 Microsoft 服务,请与服务厂商联系,并参考特定服务错误代码 2 后从网上寻得一贴,问题解决,解决原因不详,反正就是解决了. 问题描述:学校机房母盘安装Oracle10g传输到其它机器,母盘的O

AIX突然断电后hacmp无法启动的解决方法

AIX是一款类UNIX操作系统,而hacmp是用于AIX系统的一种控制应用程序,当AIX突然断电后,会出现hacmp无法启动的情况,下面小编就给大家介绍下AIX断电后hacmp无法启动的解决方法. 因为ups问题导致数据库小型机及存储等断电,hacmp不能启动, 发现jzpt1上的硬盘识别有问题,原来硬盘是从hdisk0--hdisk11,现在是hdisk2到hdisk9没有了,后面从hdisk12之后有不少硬盘,通过rmdev -Rdl hdisk2到所有末尾硬盘,cfgmgr -v重新识别,

电脑安装LMS Amesim软件后提示错误启动失败怎么解决

  电脑安装LMS Amesim软件后提示错误启动失败怎么解决           1.打开LMS Imagine.Lab Amesim 14的安装目录,C:Program Files (x86)LMSLMS Imagine.Lab Amesimv1400licensing,找到该文件夹下的rlm应用程序; 2.双击运行rlm; 3.返回桌面,再次双击打开桌面上的LMS Amesim快捷方式即可打开.

mysql-JAVA 如何 在MySQL 服务停止后 再开始时继续连接它

问题描述 JAVA 如何 在MySQL 服务停止后 再开始时继续连接它 MySQL 服务有时会自动停止,然后再运行 当它停止时 我的JAVA程序会报 com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure的错误 程序是一直反复读取数据库信息的,而当抛出这个错误后,就是MySQL的服务启动了,程序也无法读取数据库了,请问该怎么解决呢?我没有使用框架,麻烦各位了,谢谢. 解决方案 程序没