Hadoop HDFS
  1. Hadoop HDFS
  2. HDFS-1002

Secondary Name Node crash, NPE in edit log replay

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Invalid
    • Affects Version/s: 0.21.0
    • Fix Version/s: 0.21.0
    • Component/s: None
    • Labels:
      None

      Description

      An NPE in SNN, the core of the message looks like yay so:

      2010-02-25 11:54:05,834 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.lang.NullPointerException
      at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1152)
      at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1164)
      at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:1067)
      at org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:213)
      at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadEditRecords(FSEditLog.java:511)
      at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:401)
      at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:368)
      at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1172)
      at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:594)
      at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:476)
      at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:353)
      at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:317)
      at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:219)
      at java.lang.Thread.run(Thread.java:619)

      This happens even if I restart SNN over and over again.

      1. addChildNPE.patch
        4 kB
        Carlos Valiente
      2. snn_crash.tar.gz
        6.63 MB
        ryan rawson
      3. snn_log.txt
        10 kB
        ryan rawson

        Issue Links

          Activity

          Hide
          Todd Lipcon added a comment -

          Is this not a dup of HDFS-686? Can you verify that the 21 build you used that generated this edit log has that patch in it?

          Show
          Todd Lipcon added a comment - Is this not a dup of HDFS-686 ? Can you verify that the 21 build you used that generated this edit log has that patch in it?
          Show
          ryan rawson added a comment - I forgot, this is a hadoop 0.21 build, based on SVN revision 901028, its from http://github.com/apache/hadoop-hdfs/commit/de5d50187a34d35e5e1a9ea8bfa1a2fedb9a7df4 which is actually https://svn.apache.org/repos/asf/hadoop/hdfs/branches/branch-0.21@901028 Inspecting the code on my systems also verifies that yes we have this commit: http://svn.apache.org/viewvc/hadoop/hdfs/branches/branch-0.21/src/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java?p2=/hadoop/hdfs/branches/branch-0.21/src/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java&p1=/hadoop/hdfs/branches/branch-0.21/src/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java&r1=824955&r2=824954&view=diff&pathrev=824955
          Hide
          Hairong Kuang added a comment -

          NameNode is the culprit of the problem. Ryan, could you please figure out NPE is thrown on which operation in the edit log? Otherwise I need a copy of your fs image and edit log to figure out the problem. In addition, a copy of NameNode log & audit log are very helpful too.

          Show
          Hairong Kuang added a comment - NameNode is the culprit of the problem. Ryan, could you please figure out NPE is thrown on which operation in the edit log? Otherwise I need a copy of your fs image and edit log to figure out the problem. In addition, a copy of NameNode log & audit log are very helpful too.
          Hide
          ryan rawson added a comment -

          The edits log is 17 meg large, it is included in the attachments here.

          Show
          ryan rawson added a comment - The edits log is 17 meg large, it is included in the attachments here.
          Hide
          Hairong Kuang added a comment -

          Thanks! I did not notice that you had uploaded the edit log and image as well. Just to make sure that the edit log was generated using 0.21 build, right?

          Show
          Hairong Kuang added a comment - Thanks! I did not notice that you had uploaded the edit log and image as well. Just to make sure that the edit log was generated using 0.21 build, right?
          Hide
          ryan rawson added a comment -

          my JVM has this in it's lsof:
          java 10109 hadoop mem REG 8,3 832194 205563 /home/hadoop/hadoop-0.21/hdfs/hadoop-hdfs-0.21.0-SNAPSHOT.jar

          and that build is most definitely from 0.21 branch with the aforementioned revision. Unless the gremlins have come out again and changed the bits on me...

          Show
          ryan rawson added a comment - my JVM has this in it's lsof: java 10109 hadoop mem REG 8,3 832194 205563 /home/hadoop/hadoop-0.21/hdfs/hadoop-hdfs-0.21.0-SNAPSHOT.jar and that build is most definitely from 0.21 branch with the aforementioned revision. Unless the gremlins have come out again and changed the bits on me...
          Hide
          Carlos Valiente added a comment -

          Any news on this issue? I'm seeing it as well on my cluster:

          2010-03-13 15:19:48,830 INFO org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification succeeded for blk_-6710987566789746717_10247649
          2010-03-13 15:19:50,443 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from XXX.XXX.XXX.XXX
          2010-03-13 15:19:50,611 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 16959426 bytes.
          2010-03-13 15:19:50,614 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 19474 bytes.
          2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: defaultReplication = 3
          2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplication = 512
          2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: minReplication = 1
          2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplicationStreams = 2
          2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: shouldCheckForEnoughRacks = true
          2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop,dialout,video
          2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup
          2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true
          2010-03-13 15:19:50,665 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isAccessTokenEnabled=false accessKeyUpdateInterval=0 min(s), accessTokenLifetime=0 min(s)
          2010-03-13 15:19:50,694 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 105773
          2010-03-13 15:19:53,120 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files under construction = 5
          2010-03-13 15:19:53,125 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Throwable Exception in doCheckpoint: 
          2010-03-13 15:19:53,125 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.lang.NullPointerException
                  at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1152)
                  at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1164)
                  at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:1067)
                  at org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:213)
                  at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadEditRecords(FSEditLog.java:511)
                  at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:401)
                  at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:368)
                  at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1172)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:594)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:476)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:353)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:317)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:219)
                  at java.lang.Thread.run(Thread.java:619)
          

          I'm running 0.21.0-SNAPSHOT, revision 916530. I'm happy to provide the fsimage, edits and edits.new files, it it helps.

          C

          Show
          Carlos Valiente added a comment - Any news on this issue? I'm seeing it as well on my cluster: 2010-03-13 15:19:48,830 INFO org.apache.hadoop.hdfs.server.datanode.DataBlockScanner: Verification succeeded for blk_-6710987566789746717_10247649 2010-03-13 15:19:50,443 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from XXX.XXX.XXX.XXX 2010-03-13 15:19:50,611 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 16959426 bytes. 2010-03-13 15:19:50,614 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 19474 bytes. 2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: defaultReplication = 3 2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplication = 512 2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: minReplication = 1 2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: maxReplicationStreams = 2 2010-03-13 15:19:50,626 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: shouldCheckForEnoughRacks = true 2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop,dialout,video 2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup 2010-03-13 15:19:50,662 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true 2010-03-13 15:19:50,665 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isAccessTokenEnabled=false accessKeyUpdateInterval=0 min(s), accessTokenLifetime=0 min(s) 2010-03-13 15:19:50,694 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 105773 2010-03-13 15:19:53,120 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files under construction = 5 2010-03-13 15:19:53,125 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Throwable Exception in doCheckpoint: 2010-03-13 15:19:53,125 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.lang.NullPointerException at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1152) at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1164) at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:1067) at org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:213) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadEditRecords(FSEditLog.java:511) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:401) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:368) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1172) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:594) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:476) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:353) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:317) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:219) at java.lang.Thread.run(Thread.java:619) I'm running 0.21.0-SNAPSHOT, revision 916530. I'm happy to provide the fsimage, edits and edits.new files, it it helps. C
          Hide
          Hairong Kuang added a comment -

          For Ryan's edit log, NPE is thrown when adding the file /hbase/stumbles_by_userid/compaction.dir/378232123/9207375265821366914 to HDFS. NPE is thrown because for some reason the parent directory /hbase/stumbles_by_userid/compaction.dir/378232123 has not been created yet.

          Show
          Hairong Kuang added a comment - For Ryan's edit log, NPE is thrown when adding the file /hbase/stumbles_by_userid/compaction.dir/378232123/9207375265821366914 to HDFS. NPE is thrown because for some reason the parent directory /hbase/stumbles_by_userid/compaction.dir/378232123 has not been created yet.
          Hide
          Hairong Kuang added a comment -

          This happens either the parent directory is missed from fsimage or the edit log entry that create the parent directory is missed in the edit log. Before I do more investigation, could you please let me know that in your code, when you create the file /hbase/stumbles_by_userid/compaction.dir/378232123/9207375265821366914, do you EXPLICITLY create its parent directory first or use file create to IMPLICITLY create its parent directory?

          Show
          Hairong Kuang added a comment - This happens either the parent directory is missed from fsimage or the edit log entry that create the parent directory is missed in the edit log. Before I do more investigation, could you please let me know that in your code, when you create the file /hbase/stumbles_by_userid/compaction.dir/378232123/9207375265821366914, do you EXPLICITLY create its parent directory first or use file create to IMPLICITLY create its parent directory?
          Hide
          ryan rawson added a comment -

          we create the directory first, here is the relevant code:

          if (!fs.exists(dir))

          { fs.mkdirs(dir); }

          Path path = getUniqueFile(fs, dir);
          return new HFile.Writer(fs, path, blocksize,
          algorithm == null? HFile.DEFAULT_COMPRESSION_ALGORITHM: algorithm,
          c == null? KeyValue.KEY_COMPARATOR: c);

          (StoreFile.java:398 in HBase)

          In this case "getUniqueFile" generates that "9207375265821366914" filename. The constructor of HFile.Writer() will create the file using "fs.create(path)".

          Also 'dir' == "/hbase/stumbles_by_userid/compaction.dir/378232123" in this context.

          So yes we create the directory before creating the file.

          Show
          ryan rawson added a comment - we create the directory first, here is the relevant code: if (!fs.exists(dir)) { fs.mkdirs(dir); } Path path = getUniqueFile(fs, dir); return new HFile.Writer(fs, path, blocksize, algorithm == null? HFile.DEFAULT_COMPRESSION_ALGORITHM: algorithm, c == null? KeyValue.KEY_COMPARATOR: c); (StoreFile.java:398 in HBase) In this case "getUniqueFile" generates that "9207375265821366914" filename. The constructor of HFile.Writer() will create the file using "fs.create(path)". Also 'dir' == "/hbase/stumbles_by_userid/compaction.dir/378232123" in this context. So yes we create the directory before creating the file.
          Hide
          Hairong Kuang added a comment -

          I checked the attached fsimge. It does not have an entry for /hbase/stumbles_by_userid/compaction.dir/378232123. The edit log does not have a transaction for the directory either. I am guessing that there is a bug with the secondary namenode, which in 0.21 is renamed as BackupNamenode and its behavior has changed quite a lot.

          Ryan, could you please try loading the fsimage & edits log at the NameNode side to see if you see the same exception?

          Show
          Hairong Kuang added a comment - I checked the attached fsimge. It does not have an entry for /hbase/stumbles_by_userid/compaction.dir/378232123. The edit log does not have a transaction for the directory either. I am guessing that there is a bug with the secondary namenode, which in 0.21 is renamed as BackupNamenode and its behavior has changed quite a lot. Ryan, could you please try loading the fsimage & edits log at the NameNode side to see if you see the same exception?
          Hide
          Hairong Kuang added a comment -

          Is it possible that this bug is caused by HDFS-955?

          Show
          Hairong Kuang added a comment - Is it possible that this bug is caused by HDFS-955 ?
          Hide
          Hairong Kuang added a comment -

          Mark this as a blocker because losing edits can cause catastrophic problem to HDFS.

          Show
          Hairong Kuang added a comment - Mark this as a blocker because losing edits can cause catastrophic problem to HDFS.
          Hide
          Carlos Valiente added a comment -

          Similarly to openNPE.patch in HDFS-686, addChildNPE.patch avoids the 2NN crash and logs the null INode object. The diff is against http://svn.apache.org/repos/asf/hadoop/hdfs/branches/branch-0.21

          Is it safe to do that?

          Show
          Carlos Valiente added a comment - Similarly to openNPE.patch in HDFS-686 , addChildNPE.patch avoids the 2NN crash and logs the null INode object. The diff is against http://svn.apache.org/repos/asf/hadoop/hdfs/branches/branch-0.21 Is it safe to do that?
          Hide
          Hairong Kuang added a comment -

          I took a look at the image & edits that Carlos provided at HDFS-686. It clearly indicated some edit entries were missing. The missing parent directory /fields/0001/20100325_1200/c1b1301_wrep_o_12_pp_fc_tp is not in the image and no other entry in edits contains this directory.

          In this case, although addChildNPE.patch avoids the crash, it does not help get the missing directory back.

          Show
          Hairong Kuang added a comment - I took a look at the image & edits that Carlos provided at HDFS-686 . It clearly indicated some edit entries were missing. The missing parent directory /fields/0001/20100325_1200/c1b1301_wrep_o_12_pp_fc_tp is not in the image and no other entry in edits contains this directory. In this case, although addChildNPE.patch avoids the crash, it does not help get the missing directory back.
          Hide
          Konstantin Shvachko added a comment -

          This is most probably related to HDFS-909.
          I see Todd is working on it. We should get it going.

          Show
          Konstantin Shvachko added a comment - This is most probably related to HDFS-909 . I see Todd is working on it. We should get it going.
          Hide
          Todd Lipcon added a comment -

          I see Todd is working on it. We should get it going.

          I think the top patch on that JIRA is ready for review, though it may have fallen out of date. I'll swing back around on it today or tomorrow to double check that it still applies, etc.

          Show
          Todd Lipcon added a comment - I see Todd is working on it. We should get it going. I think the top patch on that JIRA is ready for review, though it may have fallen out of date. I'll swing back around on it today or tomorrow to double check that it still applies, etc.
          Hide
          Tom White added a comment -

          Todd, the patch no longer applies. Can you regenerate please?

          Show
          Tom White added a comment - Todd, the patch no longer applies. Can you regenerate please?
          Hide
          Todd Lipcon added a comment -

          Hey Tom, I think Konstantin was referring to the patch on HDFS-909 which got committed. I think this jira can probably be resolved as invalid (ie, it is a result of other bugs that cause corruption, not a bug on its own)

          Show
          Todd Lipcon added a comment - Hey Tom, I think Konstantin was referring to the patch on HDFS-909 which got committed. I think this jira can probably be resolved as invalid (ie, it is a result of other bugs that cause corruption, not a bug on its own)

            People

            • Assignee:
              Unassigned
              Reporter:
              ryan rawson
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development