Resolves the namenode after the exception stops and does not start properly

Background:

The company online uses the CDH5 ha mode, has two namenode nodes, the result of which the standby node due to some errors about edits file abnormal stop, and in the process of startup has been reported to be unable to find a variety of files.

Just beginning to suspect that the problem may only occur in the standby itself, so try Bootstrapstandby to reinitialize the standby node, but the problem remains.
And then because I try to restart ZKFC (zookeeper Failover) server, resulting in an active node to automatically switch, in the switch after the failure to switch back, also can not start the service, the error and standby node exactly the same, so the entire Hadoop cluster hung.

The problem is serious, after searching the entire Google can not find any useful information, only to the boss. Finally, the boss thought of a thought, that is, fsimage (metadata) files and edits (edit log) files are compiled into text, to see what the specific content, why load edits file will be an error.

As a result, this idea brings us to the dawn and eventually fixes the whole cluster.

Environment Introduction:
Idc2-server1:namenode, Journalnode, ZKFC
Idc2-server2:namenode, Journalnode, ZKFC
Idc2-server3:journalnode, ResourceManager

Specific process:
First, the following error occurred on the standby Namenode, and then the process was automatically closed:

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)
...
It refers to "Unknown error encountered while tailing edits." Shutting down standby NN. "

So we tried to start the standby Namenode service, and the results reported the following error:

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)
Said he couldn't find "/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 "This file.
In fact, this file is a temporary file, unimportant and has been deleted.
But on top, it reports "ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader:Encountered exception on Operation Closeop", You can see that when you load the edits file, you are prompted to not find the file when you perform the op_close operation.

At first we suspected that there might be a problem with the Fsimage file or edits file on the standby, so we executed bootstrapstandby on standby, and the change process automatically gets the latest Namenode file from the active fsimage and download and execute the new edits file from the Journalnode log server.

Sudo-u HDFs Hadoop Namenode-bootstrapstandby
However, after initialization, the same error is still encountered on loading edits.

And then, as I try to reboot the ZKFC (zookeeper Failover) service, the active Namenode automatically switches to standby, but because standby cannot take over, the active Namenode switch back, also can not restart normally, the error and standby started the same.

As a result, the entire Hadoop cluster is hung up, after searching the entire Google can not find any useful information, I called the eldest, the boss also through the above error Google does not have any useful information.
So the boss tried to grep the path above in the edits file and found some related edits files:

# 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
So we thought about whether we could find some clues from these edits files or fsimage files.
The following two articles refer to the Decompile tools for fsimage and edits files with Hadoop:
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

Some of the descriptions of edits documents give us great hope:

In case there are some problem with Hadoop cluster and the edits file is corrupted it are possible to save on least part The edits file is correct. This can do by converting the "binary edits to XML", edit it manually and then convert it back to binary.
with the above description, we understand that the edits file may be corrupted, and that it can be used as a workaround by manually modifying it after it is compiled back into binary format.
So we copy and decompile the two associated edits files found above:

# 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
After the decompile, two XML files were generated and we searched the XML file for "/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 " , and found the relevant records of Op_close and 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>
As you can see, for the "/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 occurs before op_close, so the "File does not exist" is prompted when the op_close is executed.

So we try to replace this part of the code with something else, such as the right to modify an existing file Op_close, and keep Txid 240823292 to ensure the integrity of edits files.

<RECORD>
<OPCODE>OP_SET_PERMISSIONS</OPCODE>
<DATA>
<TXID>240823292</TXID>
<SRC>/user/oozie-heylinux/.staging/job_1415171013961_37194</SRC>
<MODE>504</MODE>
</DATA>
</RECORD>
After the modification is complete, then decompile the XML file back to the binary format.

# 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
Then synchronizes the binary file to the Journalnode log server:

# 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/
Then start the Namenode service, and you can see that the error is no longer there and replaced by another file.

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)
...
Then, the next step is to repeat the above action, which sometimes can find a part of the law, you can batch the same directory repeatedly error-Op_close are replaced by the file. But more of the time is a random file, need to modify the XML file, and then compiled into binary, and then start Namenode, targeted modifications, has been repeated, until Namenode can successfully start.

We also encountered the Op_add_block error during the specific operation, causing the problem because of some op_update_block errors that occurred when the last edits file was decompile back to the binary file.
I have replaced the error section in the above way to successfully decompile the edits file back to the binary file.
The specific solution is to locate Op_add_block related configuration and replace it according to the "encountered exception on Operation Addblockop".

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
Finally, after the Namenode startup, many block losses are reported, and the solution is to remove the block of these errors by fsck.

# Hadoop fsck/-files-blocks-locations | Tee-a Fsck.out
It then obtains all block information in Fsck.out and performs the "Hadoop fsck/-move" plus block path for deletion.

Finally, quit SafeMode, and life becomes better again.

# Hadoop Dfsadmin-safemode leave
PS: In the later, the above problem again, by analyzing what we found to be caused by a bug in Hadoop, began to exist from 2.10-beta:
https:/ /issues.apache.org/jira/browse/hdfs-6527
https://issues.apache.org/jira/browse/HDFS-6647
wants to avoid the recurrence of such problems completely , you must upgrade Hadoop to more than 2.5 versions, and the corresponding CDH version is 5.2.0