NameNode 启动失败 - There appears to be a gap in the edit log. We expected txid xxx, but got tx

场景

NameNode迁移，导致一个节点无法启动

异常

在Namenode主动迁移，或者Namenode机器挂掉无法恢复时，我们需要Namenode节点迁移，迁移经常会出现一个NameNode启动成功，另外一个standby启动失败，报错如下

2019-09-27 15:19:23,818 WARN org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Encountered exception loading fsimage
java.io.IOException: There appears to be a gap in the edit log.  We expected txid 266899638, but got txid 267088002.at org.apache.hadoop.hdfs.server.namenode.MetaRecoveryContext.editLogLoaderPrompt(MetaRecoveryContext.java:94)at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:230)at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:158)at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:882)at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:739)at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:317)at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.loadFSImage(FSNamesystem.java:1112)at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.loadFromDisk(FSNamesystem.java:738)at org.apache.hadoop.hdfs.server.namenode.NameNode.loadNamesystem(NameNode.java:665)at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:727)at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:950)at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:929)at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:1653)at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:1720)
2019-09-27 15:19:23,832 INFO org.eclipse.jetty.server.handler.ContextHandler: Stopped o.e.j.w.WebAppContext@4c398c80{/,null,UNAVAILABLE}{/hdfs}
2019-09-27 15:19:23,838 INFO org.eclipse.jetty.server.AbstractConnector: Stopped ServerConnector@75390459{HTTP/1.1,[http/1.1]}{fwqml009.zh:9870}
2019-09-27 15:19:23,838 INFO org.eclipse.jetty.server.handler.ContextHandler: Stopped o.e.j.s.ServletContextHandler@4983159f{/static,file:///opt/cloudera/parcels/CDH-6.0.0-1.cdh6.0.0.p0.537114/lib/hadoop-hdfs/webapps/static/,UNAVAILABLE}
2019-09-27 15:19:23,839 INFO org.eclipse.jetty.server.handler.ContextHandler: Stopped o.e.j.s.ServletContextHandler@753432a2{/logs,file:///var/log/hadoop-hdfs/,UNAVAILABLE}
2019-09-27 15:19:23,840 INFO org.apache.hadoop.metrics2.impl.MetricsSystemImpl: Stopping NameNode metrics system...
2019-09-27 15:19:23,841 INFO org.apache.hadoop.metrics2.impl.MetricsSystemImpl: NameNode metrics system stopped.
2019-09-27 15:19:23,842 INFO org.apache.hadoop.metrics2.impl.MetricsSystemImpl: NameNode metrics system shutdown complete.
2019-09-27 15:19:23,842 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: Failed to start namenode.
java.io.IOException: There appears to be a gap in the edit log.  We expected txid 266899638, but got txid 267088002.at org.apache.hadoop.hdfs.server.namenode.MetaRecoveryContext.editLogLoaderPrompt(MetaRecoveryContext.java:94)at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:230)at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:158)at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:882)at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:739)at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:317)at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.loadFSImage(FSNamesystem.java:1112)at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.loadFromDisk(FSNamesystem.java:738)at org.apache.hadoop.hdfs.server.namenode.NameNode.loadNamesystem(NameNode.java:665)at org.apache.hadoop.hdfs.server.namenode.NameNode.initialize(NameNode.java:727)at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:950)at org.apache.hadoop.hdfs.server.namenode.NameNode.<init>(NameNode.java:929)at org.apache.hadoop.hdfs.server.namenode.NameNode.createNameNode(NameNode.java:1653)at org.apache.hadoop.hdfs.server.namenode.NameNode.main(NameNode.java:1720)
2019-09-27 15:19:23,844 INFO org.apache.hadoop.util.ExitUtil: Exiting with status 1: java.io.IOException: There appears to be a gap in the edit log.  We expected txid 266899638, but got txid 267088002.

在网上一搜上面异常，基本都是
hadoop namenode -recover
或者让我格式化NameNode...（线上数据不能这么玩~）

我的场景使用 -recover 会报错，:(

原因分析

原因是 standby Namenode启动会去 jn （JournalNode，Namenode HA场景下，是通过JournalNode进行过数据同步）获取数据，但是jn 没有，具体查看一下

上面日志提示 We expected txid 266899638, but got txid 267088002. 也就是Namenode想要获取266899638这个edit，但是获取到的是267088002，查看 jn 目录下，发现的确只有267088002 即：edits_0000000000267088002-0000000000267088002

[root@jast009 current]# ll
总用量 480380
-rw-r--r-- 1 hdfs hdfs         8 9月  27 15:23 committed-txid
-rw-r--r-- 1 hdfs hdfs   2506691 9月  26 15:58 committed-txid.bak
-rw-r--r-- 1 hdfs hdfs        25 9月  26 10:30 edits_0000000000267088002-0000000000267088002
-rw-r--r-- 1 hdfs hdfs       755 9月  26 10:37 edits_0000000000267088003-0000000000267088010
-rw-r--r-- 1 hdfs hdfs       756 9月  26 10:39 edits_0000000000267088011-0000000000267088018
-rw-r--r-- 1 hdfs hdfs      1471 9月  26 10:41 edits_0000000000267088019-0000000000267088032
-rw-r--r-- 1 hdfs hdfs       756 9月  26 10:43 edits_0000000000267088033-0000000000267088040
-rw-r--r-- 1 hdfs hdfs      1470 9月  26 10:45 edits_0000000000267088041-0000000000267088054
-rw-r--r-- 1 hdfs hdfs      1472 9月  26 10:47 edits_0000000000267088055-0000000000267088068
-rw-r--r-- 1 hdfs hdfs   1048576 9月  26 10:47 edits_0000000000267088069-0000000000267088069
-rw-r--r-- 1 hdfs hdfs     12401 9月  26 10:52 edits_0000000000267088070-0000000000267088170
-rw-r--r-- 1 hdfs hdfs   2580282 9月  26 10:54 edits_0000000000267088171-0000000000267104853
-rw-r--r-- 1 hdfs hdfs    309195 9月  26 10:56 edits_0000000000267104854-0000000000267106831
-rw-r--r-- 1 hdfs hdfs    264231 9月  26 10:58 edits_0000000000267106832-0000000000267108442
-rw-r--r-- 1 hdfs hdfs    915772 9月  26 11:00 edits_0000000000267108443-0000000000267114308
-rw-r--r-- 1 hdfs hdfs    727526 9月  26 11:02 edits_0000000000267114309-0000000000267118780
-rw-r--r-- 1 hdfs hdfs   3411288 9月  26 11:04 edits_0000000000267118781-0000000000267139507
-rw-r--r-- 1 hdfs hdfs   1048576 9月  26 11:04 edits_0000000000267139508-0000000000267139508
-rw-r--r-- 1 hdfs hdfs     17352 9月  26 11:10 edits_0000000000267139509-0000000000267139673
-rw-r--r-- 1 hdfs hdfs   1282451 9月  26 11:12 edits_0000000000267139674-0000000000267146671
-rw-r--r-- 1 hdfs hdfs   2714992 9月  26 11:14 edits_0000000000267146672-0000000000267164211
-rw-r--r-- 1 hdfs hdfs    340434 9月  26 11:17 edits_0000000000267164212-0000000000267166258
-rw-r--r-- 1 hdfs hdfs    335975 9月  26 11:19 edits_0000000000267166259-0000000000267168268
-rw-r--r-- 1 hdfs hdfs    423730 9月  26 11:21 edits_0000000000267168269-0000000000267171145
-rw-r--r-- 1 hdfs hdfs   1048576 9月  26 15:29 edits_0000000000267171146-0000000000267174696
-rw-r--r-- 1 hdfs hdfs       757 9月  26 15:34 edits_0000000000267233868-0000000000267233875
-rw-r--r-- 1 hdfs hdfs   1048576 9月  26 15:55 edits_0000000000267233876-0000000000267233972
-rw-r--r-- 1 hdfs hdfs  22020096 9月  27 10:53 edits_0000000000267233973-0000000000267396690
-rw-r--r-- 1 hdfs hdfs 382730240 9月  27 15:23 edits_inprogress_0000000000267396691
-rw-r--r-- 1 hdfs hdfs         3 9月  27 11:00 last-promised-epoch
-rw-r--r-- 1 hdfs hdfs         3 9月  27 11:00 last-writer-epoch
drwxr-xr-x 2 hdfs hdfs         6 9月  27 11:00 paxos
-rw-r--r-- 1 hdfs hdfs       136 9月  26 10:30 VERSION

我们尝试将需要的数据copy到jn 目录下，并重启，看看是否可以恢复。

我们去NameNode目录下（两个NameNode节点目录都看一下）将所有edits_0xxxx文件全部复制到 jn节点保存目录

这里复制过程省略....... scp即可，看自己心情

文件复制完成后，需要重启 JN 节点（JN 都停了的话Namenode也需要停），是使新导入数据生效