checkpoint异常需要手动合并editlog

最近我们集群的SNN发生了一些异常,记录下。

关于SNN的作用,见我以前的一篇文章

关于txid

txid用于标记一条editlog。
一般在ANN的dfs.name.dir有几种文件:

  • fsimage_XXX,表示这个fsimage文件已经将txid=XXX的editlog合并进来了。这种文件必定有一个同名的md5文件对应。
  • fsimage.ckpt_XXX,表示正在做checkpoint的一个fsimage文件,其实就是正在从SNN copy的一个文件
  • edits_XXX-YYY,包含从XXX到YYY的所有editlog
  • edits_inprogress_XXX,当前正在写的editlog文件,初始的txid是XXX

NN启动时会加载txid最大的一个fsimage_XXX文件。然后读取XXX之后的所有editlog并合并。如果editlog不连续,NN无法启动。
当NN启动完成后,会自动做一次checkpoint。之后开始写新的edits_inprogress文件。

异常原因

4月30号删除了大量数据,fsimage文件大小从6G减小到3G。
由于找不回当时的日志了,不知道发生了什么。原来的fsimage_AAA有6G左右,经过一次checkpoint后生成了一个3G多的fsimage_BBB文件。
但这个BBB不是任何edits文件的边界,所以无法基于这个fsimage_BBB文件继续合并editlog。
journalnode的日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
2015-05-02 00:00:14,323 WARN org.apache.hadoop.ipc.Server: IPC Server handler 4 on 8485, call org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocol.getEd
itLogManifest from 172.17.1.10:48924 Call#572756 Retry#0: error: java.lang.IllegalStateException: Asked for firstTxId 1604743888 which is in the middle of fi
le /home/hadoop/jn/hz-cluster1/current/edits_0000000001604742607-0000000001604746980
java.lang.IllegalStateException: Asked for firstTxId 1604743888 which is in the middle of file /home/hadoop/jn/hz-cluster1/current/edits_0000000001604742607-
0000000001604746980
at org.apache.hadoop.hdfs.server.namenode.FileJournalManager.getRemoteEditLogs(FileJournalManager.java:198)
at org.apache.hadoop.hdfs.qjournal.server.Journal.getEditLogManifest(Journal.java:640)
at org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.getEditLogManifest(JournalNodeRpcServer.java:181)
at org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.getEditLogManifest(QJournalProtocolServerSideTranslatorPB.java:203)
at org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:17453)
at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:585)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:928)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2048)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2044)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:396)
at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1491)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2042)

无论是NN直接读取editlog,还是通过JN读取editlog,都必须从一个edits文件的边界开始读,不能一个中间的txid开始读。
从生成这个文件开始,SNN无论尝试rollEditLog还是checkpoint都会直接失败。因为读取editlog会直接抛异常。
无法rollEditLog,导致ANN一直在写edits_in_process文件,这个文件非常大,将近10G。
无法checkpoint,导致ANN的fsimage停在BBB版本。如果failover肯定会失败。

解决过程

4月30号之后,这个问题一直没被发现。
5月10号,萧山ANN出了点问题,碰到一个bug:HDFS-6289
5月11号,为了防止同样的问题,打算重启下滨江的SNN(hadoop0.photo)。发现启动后总是显示有missing block。虽然能收到所有节点的心跳。
检查了hadoop0的日志,发现了之前说的读取editlog的异常。怀疑是元数据有问题。
看了下dfs.name.dir,发现了一个10G的edits文件,非常震惊。。。分析日志后发现了fsimage_BBB文件的异常。
万幸这个问题不影响ANN的正常功能。但风险很大,一旦ANN挂掉,就起不来了。

让SNN合并editlog

基于fsimage_BBB文件NN不可能正常启动。好在NN会保留fsimage的2个备份。原来6G多的fsimage_AAA还在,这个文件是正常的,AAA之后所有的editlog也在。只要基于这个文件,手动生成最新的fsimage即可。
首先尝试让hadoop0自己去合并,删掉dfs.name.dir中的fsimage_BBB即可。SNN启动过程中会加载txid最大的一个fsimage。
由于hadoop0是HA的配置,所以所有editlog都是从journal node中读取的。
总共有10G左右的editlog要合并(10多天的量),editlog要一条一条回放,要15小时左右。
于是放着NN进程自己合并,明天再来观察。

5月12号,检查hadoop0的日志,发现虽然合并editlog成功了,但之后报了一个kerberos的异常。NN还是无法启动。
猜测是kerberos ticket超过10小时过期了,之后NN读取journal node异常,直接自杀。
正常情况下NN中应该有线程负责定期更新ticket的,但合并editlog的过程却没有更新,因为NN相关的服务还没启动。
可能设计的时候没想到这种情况。

单独启动一个NN

尝试启动一个单机的、关闭security的NN进程,用来合并editlog。这样NN会直接从dfs.name.dir读文件,而不是读journal node,也不存在kerberos的问题了。
合并后的文件应该可以通用的。
如果这个方法还不行,就只能分析fsimage的结构,自己写程序处理了。

在inspur131上直接copy一份tar包,修改配置,只保留几个配置文件:

1
2
3
4
5
6
hadoop@inspur131:~/jxy/edits/hadoop-2.2.0$ ls -lh etc/hadoop
总用量 24K
-rw-r--r-- 1 hadoop netease 441 512 12:20 core-site.xml
-rw-r--r-- 1 hadoop netease 4.0K 512 12:21 hadoop-env.sh
-rw-r--r-- 1 hadoop netease 575 512 12:20 hdfs-site.xml
-rw-r--r-- 1 hadoop netease 9.3K 512 12:20 log4j.properties

core-site.xml里只保留一个属性:

1
2
3
4
<property>
<name>fs.defaultFS</name>
<value>hdfs://inspur131.photo.163.org:8020</value>
</property>

hdfs-site.xml也只保留一个属性:

1
2
3
4
<property>
<name>dfs.name.dir</name>
<value>/home/hadoop/jxy/edits/name</value>
</property>

hadoop-env.sh里只设置JAVA_HOME属性。
以上就是一个单机的NN进程需要的最小配置了。

将fsimage_AAA文件和需要的所有edits文件,从NN拷到inspur131上,/home/hadoop/jxy/edits/name目录。然后启动NN:

1
2
# 不开启security,也就不用sudo了
hadoop@inspur131:~/jxy/edits/hadoop-2.2.0/sbin$ ./hadoop-daemon.sh start namenode

由于没有设置HADOOP_LOG_DIR,日志会放在HADOOP_HOME/logs。
在NN的web界面可以看到合并的进度。

5月13号,inspur131上的NN进程合并完毕,总共用了15小时左右:

由于没有启动DN,所以NN会一直处于safemode。
观察dfs.name.dir,已成功生成fsimage文件。
editlog合并结束会自动saving checkpoint,见上图,不要自己-saveNamespace。

1
2
3
4
5
6
7
8
9
10
11
hadoop@inspur131:~/jxy/edits/name/current$ ls -lh | tail
-rw-r--r-- 1 hadoop netease 2.7M 5月 12 11:51 edits_0000000001604746981-0000000001604768189
-rw-r--r-- 1 hadoop netease 10G 5月 12 11:55 edits_0000000001604768190-0000000001681027556
-rw-r--r-- 1 hadoop netease 16M 5月 12 11:55 edits_0000000001681027557-0000000001681148275
-rw-r--r-- 1 hadoop netease 1.0M 5月 13 05:50 edits_inprogress_0000000001681148276
-rw-r--r-- 1 hadoop netease 6.3G 5月 12 11:57 fsimage_0000000001604721018
-rw-r--r-- 1 hadoop netease 62 5月 12 11:57 fsimage_0000000001604721018.md5
-rw-r--r-- 1 hadoop netease 3.2G 5月 13 05:50 fsimage_0000000001681148275
-rw-r--r-- 1 hadoop netease 62 5月 13 05:50 fsimage_0000000001681148275.md5
-rw-r--r-- 1 hadoop netease 11 5月 13 05:50 seen_txid
-rw-r--r-- 1 hadoop netease 207 5月 13 05:50 VERSION

启动SNN

将最新生成的fsimage文件拷到hadoop0,启动SNN。SNN会合并一些最新的editlog(11号、12号新生成的editlog,有2G多)。
接下来SNN进程却卡住了。接着有用户反应无法读写hdfs。观察RM界面,job能提交上来,但是一直在ACCPETED状态,无法运行。
大概持续了20分钟,杀掉SNN进程后,用户使用恢复正常。
由于HA集群中,客户端要先去查询hadoop0是否active。hadoop0卡住导致用户也无法使用。相关原理见之前的文章

猜测SNN卡住是在处理DN的心跳。所以打算利用NN的白名单机制,一次只加几个DN节点。
重新尝试启动SNN,白名单里只有一个DN。启动后SNN也是卡住了,但却没有影响用户的读写。过了10几分钟,NN回复正常。
尝试在白名单里加更多的DN节点,每次SNN都会卡一阵,但不阻塞hdfs读写。
最后所有DN都加进去,SNN成功离开safemode。
观察dfs.name.dir,checkpoint也正常了。

后续

  1. SNN为什么会卡住?当时用jstack看是卡在一个读取editlog的线程上。但具体原因不明。
  2. 当时急于回复服务,很多现场没能保留下来。日志也找不回来了。以后应该注意下。
  3. 应该监控checkpoint过程。两种方式:监控SNN的日志,看是否正常触发;或者监控ANN的dfs.name.dir,看是否定期生成editlog和fsimage。