[HDFS-9477] namenode starts failed:FSEditLogLoader: Encountered exception on operation TimesOp

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.7.0
• Component/s: namenode

Environment

Ubuntu 12.04.1 LTS, java version "1.7.0_79"

• Assignee: aplee
• Reporter: aplee
• Due: 30/Nov/15
• Created: 30/Nov/15 02:23
• Updated: 06/Sep/18 13:18
• Resolved: 28/Nov/17 11:16

Description

backup namenode start failed, log below:
2015-11-28 14:09:13,462 ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader: Encountered exception on operation TimesOp [length=0, path=/.reserved/.inodes/2346114, mtime=-1, atime=1448692924700, opCode=OP_TIMES, txid=14774180]
java.lang.NullPointerException
at org.apache.hadoop.hdfs.server.namenode.FSDirAttrOp.unprotectedSetTimes(FSDirAttrOp.java:473)
at org.apache.hadoop.hdfs.server.namenode.FSDirAttrOp.unprotectedSetTimes(FSDirAttrOp.java:299)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.applyEditLogOp(FSEditLogLoader.java:629)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:234)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:143)
at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:832)
at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:813)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.doTailEdits(EditLogTailer.java:232)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:331)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$200(EditLogTailer.java:284)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:301)
at org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:415)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:297)
2015-11-28 14:09:13,572 FATAL org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer: Unknown error encountered while tailing edits. Shutting down standby NN.
java.io.IOException: java.lang.NullPointerException
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:244)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:143)
at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:832)
at org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:813)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.doTailEdits(EditLogTailer.java:232)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:331)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$200(EditLogTailer.java:284)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:301)
at org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:415)
at org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:297)
Caused by: java.lang.NullPointerException
at org.apache.hadoop.hdfs.server.namenode.FSDirAttrOp.unprotectedSetTimes(FSDirAttrOp.java:473)
at org.apache.hadoop.hdfs.server.namenode.FSDirAttrOp.unprotectedSetTimes(FSDirAttrOp.java:299)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.applyEditLogOp(FSEditLogLoader.java:629)
at org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:234)
... 9 more
2015-11-28 14:09:13,574 INFO org.apache.hadoop.util.ExitUtil: Exiting with status 1
2015-11-28 14:09:13,575 INFO org.apache.hadoop.hdfs.server.namenode.NameNode: SHUTDOWN_MSG:

I found record in Edits, but I don't know how this record generated

<RECORD>
<OPCODE>OP_TIMES</OPCODE>
<DATA>
<TXID>14774180</TXID>
<LENGTH>0</LENGTH>
<PATH>/.reserved/.inodes/2346114</PATH>
<MTIME>-1</MTIME>
<ATIME>1448692924700</ATIME>
</DATA>
</RECORD>

Issue Links

• Blocked: HDFS-13901 INode access time is ignored because of race between open and rename
• is duplicated by: HDFS-8269 getBlockLocations() does not resolve the .reserved path and generates incorrect edit logs when updating the atime