FAQ
Of course I discovered this after it became a problem, and now am not sure what to do next without losing data/metadata.

Background: I just added two nodes to a CDH 4.1.3 cluster. The new nodes got installed automatically with 4.2, so I went ahead and upgraded the other nodes too. Now, after the upgrade, the namenode won't start.

This is the around the end of the logfile:

java.lang.AssertionError: Should not purge more edits than required to restore: 165186 should be <= 75814

The /data/N/dfs/nn/current directories have a TON of files in them (70,130 in each, replicated across 3 directories), which leads me to believe the metadata isn't updating properly. The previous.checkpoint directory is from Jan 30!

My first thought, before I dug into it further, is that my upgrade to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that the old data would predate that.

The namenode log indicates it dutifully goes through all the edits:

2013-03-20 13:18:42,836 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to transaction ID 75814
2013-03-20 13:18:42,837 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of size 1048576 edits # 1 loaded in 0 seconds
2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression

But then decides there are too many? And I have no idea where it is getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_ files in the current directory). I don't think any metadata was lost, but am not sure.

--
Dan Bongert dbongert@ssc.wisc.edu
SSCC Linux System Administrator (608) 262-9857

Search Discussions

  • Dan Bongert at Mar 21, 2013 at 2:50 pm
    I reviewed my records, and Jan 30 was indeed when I upgraded from CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be from then.

    My first thought was that I didn't finalize the metadata after the 3u5 -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks afterwards. I am not sure if the presence of multiple fsimage files corroborates that or not:

    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40 fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40 fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18 fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18 fsimage_0000000000000185306.md5

    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan 30 as well:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I delete the 70k edits_* files, I'm going to lose nearly two months of edits? Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am not sure what to do next without losing data/metadata.

    Background: I just added two nodes to a CDH 4.1.3 cluster. The new nodes got installed automatically with 4.2, so I went ahead and upgraded the other nodes too. Now, after the upgrade, the namenode won't start.

    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required to restore: 165186 should be <= 75814

    The /data/N/dfs/nn/current directories have a TON of files in them (70,130 in each, replicated across 3 directories), which leads me to believe the metadata isn't updating properly. The previous.checkpoint directory is from Jan 30!

    My first thought, before I dug into it further, is that my upgrade to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that the old data would predate that.

    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to transaction ID 75814
    2013-03-20 13:18:42,837 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression

    But then decides there are too many? And I have no idea where it is getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_ files in the current directory). I don't think any metadata was lost, but am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857
  • Harsh J at Mar 21, 2013 at 2:53 pm
    Hi Dan,

    Can you pastebin or send along your full crashing NN log to us so we
    can take a closer look?

    Note that the "image/fsimage" is not the valid fsimage. The current/
    dir is what you should look at and is the right fsimage.
    On Thu, Mar 21, 2013 at 8:20 PM, Dan Bongert wrote:
    I reviewed my records, and Jan 30 was indeed when I upgraded from CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be from then.

    My first thought was that I didn't finalize the metadata after the 3u5 -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks afterwards. I am not sure if the presence of multiple fsimage files corroborates that or not:

    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40 fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40 fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18 fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18 fsimage_0000000000000185306.md5

    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan 30 as well:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I delete the 70k edits_* files, I'm going to lose nearly two months of edits? Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am not sure what to do next without losing data/metadata.

    Background: I just added two nodes to a CDH 4.1.3 cluster. The new nodes got installed automatically with 4.2, so I went ahead and upgraded the other nodes too. Now, after the upgrade, the namenode won't start.

    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required to restore: 165186 should be <= 75814

    The /data/N/dfs/nn/current directories have a TON of files in them (70,130 in each, replicated across 3 directories), which leads me to believe the metadata isn't updating properly. The previous.checkpoint directory is from Jan 30!

    My first thought, before I dug into it further, is that my upgrade to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that the old data would predate that.

    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to transaction ID 75814
    2013-03-20 13:18:42,837 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression

    But then decides there are too many? And I have no idea where it is getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_ files in the current directory). I don't think any metadata was lost, but am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857


    --
    Harsh J

    --
  • Dan Bongert at Mar 21, 2013 at 2:58 pm
    Here's the end of the file. There are tons of sequences like it starts with, and then it decides that it can't start the namenode.

    http://pastebin.com/WBMdjbF1
    On Mar 21, 2013, at 9:53 AM, Harsh J wrote:

    Hi Dan,

    Can you pastebin or send along your full crashing NN log to us so we
    can take a closer look?

    Note that the "image/fsimage" is not the valid fsimage. The current/
    dir is what you should look at and is the right fsimage.
    On Thu, Mar 21, 2013 at 8:20 PM, Dan Bongert wrote:
    I reviewed my records, and Jan 30 was indeed when I upgraded from CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be from then.

    My first thought was that I didn't finalize the metadata after the 3u5 -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks afterwards. I am not sure if the presence of multiple fsimage files corroborates that or not:

    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40 fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40 fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18 fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18 fsimage_0000000000000185306.md5

    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan 30 as well:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I delete the 70k edits_* files, I'm going to lose nearly two months of edits? Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am not sure what to do next without losing data/metadata.

    Background: I just added two nodes to a CDH 4.1.3 cluster. The new nodes got installed automatically with 4.2, so I went ahead and upgraded the other nodes too. Now, after the upgrade, the namenode won't start.

    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required to restore: 165186 should be <= 75814

    The /data/N/dfs/nn/current directories have a TON of files in them (70,130 in each, replicated across 3 directories), which leads me to believe the metadata isn't updating properly. The previous.checkpoint directory is from Jan 30!

    My first thought, before I dug into it further, is that my upgrade to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that the old data would predate that.

    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to transaction ID 75814
    2013-03-20 13:18:42,837 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression

    But then decides there are too many? And I have no idea where it is getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_ files in the current directory). I don't think any metadata was lost, but am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857


    --
    Harsh J

    --
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857
  • Todd Lipcon at Mar 25, 2013 at 8:09 am
    Hi Dan,

    Can you try setting dfs.namenode.max.extra.edits.segments.retained to a
    very large number, like 1000000?

    I think this should workaround the bug you're hitting.

    Thanks
    -Todd
    On Thu, Mar 21, 2013 at 7:58 AM, Dan Bongert wrote:

    Here's the end of the file. There are tons of sequences like it starts
    with, and then it decides that it can't start the namenode.

    http://pastebin.com/WBMdjbF1
    On Mar 21, 2013, at 9:53 AM, Harsh J wrote:

    Hi Dan,

    Can you pastebin or send along your full crashing NN log to us so we
    can take a closer look?

    Note that the "image/fsimage" is not the valid fsimage. The current/
    dir is what you should look at and is the right fsimage.
    On Thu, Mar 21, 2013 at 8:20 PM, Dan Bongert wrote:
    I reviewed my records, and Jan 30 was indeed when I upgraded from
    CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be
    from then.
    My first thought was that I didn't finalize the metadata after the 3u5
    -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks afterwards.
    I am not sure if the presence of multiple fsimage files corroborates that
    or not:
    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40 fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40
    fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18 fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18
    fsimage_0000000000000185306.md5
    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan 30
    as well:
    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I
    delete the 70k edits_* files, I'm going to lose nearly two months of edits?
    Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am not
    sure what to do next without losing data/metadata.
    Background: I just added two nodes to a CDH 4.1.3 cluster. The new
    nodes got installed automatically with 4.2, so I went ahead and upgraded
    the other nodes too. Now, after the upgrade, the namenode won't start.
    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required to
    restore: 165186 should be <= 75814
    The /data/N/dfs/nn/current directories have a TON of files in them
    (70,130 in each, replicated across 3 directories), which leads me to
    believe the metadata isn't updating properly. The previous.checkpoint
    directory is from Jan 30!
    My first thought, before I dug into it further, is that my upgrade to
    4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that
    the old data would predate that.
    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO
    org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding
    stream
    '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to
    transaction ID 75814
    2013-03-20 13:18:42,837 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file
    /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306,
    /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306,
    /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of
    size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    But then decides there are too many? And I have no idea where it is
    getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_
    files in the current directory). I don't think any metadata was lost, but
    am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857


    --
    Harsh J

    --
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857

    --
    Todd Lipcon
    Software Engineer, Cloudera

    --
  • Dan Bongert at Mar 26, 2013 at 3:42 pm
    Thanks Todd, that did allow the namenode to start up. However, I'm still baffled why this happened in the first place (and how to prevent it in the future). Why are there tens of thousands of edit files? Is it because I either forgot to finalize the metadata after the last upgrade I did, or that the finalization didn't complete properly? Or something else entirely? Obviously it's not normal behavior, and I'd like to fix the problem before it gets worse.
    On Mar 25, 2013, at 3:08 AM, Todd Lipcon wrote:

    Hi Dan,

    Can you try setting dfs.namenode.max.extra.edits.segments.retained to a very large number, like 1000000?

    I think this should workaround the bug you're hitting.

    Thanks
    -Todd

    On Thu, Mar 21, 2013 at 7:58 AM, Dan Bongert wrote:
    Here's the end of the file. There are tons of sequences like it starts with, and then it decides that it can't start the namenode.

    http://pastebin.com/WBMdjbF1
    On Mar 21, 2013, at 9:53 AM, Harsh J wrote:

    Hi Dan,

    Can you pastebin or send along your full crashing NN log to us so we
    can take a closer look?

    Note that the "image/fsimage" is not the valid fsimage. The current/
    dir is what you should look at and is the right fsimage.
    On Thu, Mar 21, 2013 at 8:20 PM, Dan Bongert wrote:
    I reviewed my records, and Jan 30 was indeed when I upgraded from CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be from then.

    My first thought was that I didn't finalize the metadata after the 3u5 -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks afterwards. I am not sure if the presence of multiple fsimage files corroborates that or not:

    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40 fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40 fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18 fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18 fsimage_0000000000000185306.md5

    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan 30 as well:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I delete the 70k edits_* files, I'm going to lose nearly two months of edits? Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am not sure what to do next without losing data/metadata.

    Background: I just added two nodes to a CDH 4.1.3 cluster. The new nodes got installed automatically with 4.2, so I went ahead and upgraded the other nodes too. Now, after the upgrade, the namenode won't start.

    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required to restore: 165186 should be <= 75814

    The /data/N/dfs/nn/current directories have a TON of files in them (70,130 in each, replicated across 3 directories), which leads me to believe the metadata isn't updating properly. The previous.checkpoint directory is from Jan 30!

    My first thought, before I dug into it further, is that my upgrade to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense that the old data would predate that.

    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding stream '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to transaction ID 75814
    2013-03-20 13:18:42,837 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306, /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression

    But then decides there are too many? And I have no idea where it is getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_ files in the current directory). I don't think any metadata was lost, but am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857


    --
    Harsh J

    --
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857




    --
    Todd Lipcon
    Software Engineer, Cloudera

    --

    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857
  • Aaron T. Myers at Mar 26, 2013 at 5:14 pm
    Hi Dan,

    I agree this isn't normal behavior, but we'll need some more info to be
    able to answer the question definitively. Are you running HA, or a setup
    with an NN and Secondary NN? If HA, are you running with QJM or FJM? Could
    you perhaps share some logs with us from the NN from when it was running
    with tens of thousands of edits files? Could you also send us the output of
    `ls -l' of one of the NN edits dirs? Note that the logs may have some
    potentially sensitive info in there like HDFS filenames, so if you'd rather
    send those off-list that's totally fine.


    --
    Aaron T. Myers
    Software Engineer, Cloudera

    On Tue, Mar 26, 2013 at 8:42 AM, Dan Bongert wrote:

    Thanks Todd, that did allow the namenode to start up. However, I'm still
    baffled why this happened in the first place (and how to prevent it in the
    future). Why are there tens of thousands of edit files? Is it because I
    either forgot to finalize the metadata after the last upgrade I did, or
    that the finalization didn't complete properly? Or something else entirely?
    Obviously it's not normal behavior, and I'd like to fix the problem before
    it gets worse.
    On Mar 25, 2013, at 3:08 AM, Todd Lipcon wrote:

    Hi Dan,

    Can you try setting dfs.namenode.max.extra.edits.segments.retained to a
    very large number, like 1000000?
    I think this should workaround the bug you're hitting.

    Thanks
    -Todd

    On Thu, Mar 21, 2013 at 7:58 AM, Dan Bongert wrote:
    Here's the end of the file. There are tons of sequences like it starts
    with, and then it decides that it can't start the namenode.
    http://pastebin.com/WBMdjbF1
    On Mar 21, 2013, at 9:53 AM, Harsh J wrote:

    Hi Dan,

    Can you pastebin or send along your full crashing NN log to us so we
    can take a closer look?

    Note that the "image/fsimage" is not the valid fsimage. The current/
    dir is what you should look at and is the right fsimage.
    On Thu, Mar 21, 2013 at 8:20 PM, Dan Bongert wrote:
    I reviewed my records, and Jan 30 was indeed when I upgraded from
    CDH3u5 to 4.1.2, so that makes sense that the previous.checkpoint would be
    from then.
    My first thought was that I didn't finalize the metadata after the
    3u5 -> 4.1.2 upgrade, but I'm pretty sure I did that a couple weeks
    afterwards. I am not sure if the presence of multiple fsimage files
    corroborates that or not:
    hadoop1(6) /data/2/dfs/nn/current# ll *fsimage*
    -rw-r--r-- 1 hdfs hdfs 1036854 Feb 18 11:40
    fsimage_0000000000000075813
    -rw-r--r-- 1 hdfs hdfs 62 Feb 18 11:40
    fsimage_0000000000000075813.md5
    -rw-r--r-- 1 hdfs hdfs 1077298 Mar 20 13:18
    fsimage_0000000000000185306
    -rw-r--r-- 1 hdfs hdfs 62 Mar 20 13:18
    fsimage_0000000000000185306.md5
    Of course the real fsimage file is dated Jan 30:

    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/nn/image/fsimage

    And the secondary name node info also hasn't been updated since Jan
    30 as well:
    -rw-r--r-- 1 hdfs hdfs 157 Jan 30 13:52 /data/2/dfs/snn/image/fsimage

    Realistically, what are my options at this point? I assume that if I
    delete the 70k edits_* files, I'm going to lose nearly two months of edits?
    Or will the actual data on disk not be changed?
    On Mar 20, 2013, at 2:03 PM, Dan Bongert wrote:

    Of course I discovered this after it became a problem, and now am
    not sure what to do next without losing data/metadata.
    Background: I just added two nodes to a CDH 4.1.3 cluster. The new
    nodes got installed automatically with 4.2, so I went ahead and upgraded
    the other nodes too. Now, after the upgrade, the namenode won't start.
    This is the around the end of the logfile:

    java.lang.AssertionError: Should not purge more edits than required
    to restore: 165186 should be <= 75814
    The /data/N/dfs/nn/current directories have a TON of files in them
    (70,130 in each, replicated across 3 directories), which leads me to
    believe the metadata isn't updating properly. The previous.checkpoint
    directory is from Jan 30!
    My first thought, before I dug into it further, is that my upgrade
    to 4.1.3 (on February 12-13) caused the issue, but it doesn't make sense
    that the old data would predate that.
    The namenode log indicates it dutifully goes through all the edits:

    2013-03-20 13:18:42,836 INFO
    org.apache.hadoop.hdfs.server.namenode.EditLogInputStream: Fast-forwarding
    stream
    '/data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306' to
    transaction ID 75814
    2013-03-20 13:18:42,837 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Edits file
    /data/3/dfs/nn/current/edits_0000000000000185306-0000000000000185306,
    /data/4/dfs/nn/current/edits_0000000000000185306-0000000000000185306,
    /data/2/dfs/nn/current/edits_0000000000000185306-0000000000000185306 of
    size 1048576 edits # 1 loaded in 0 seconds
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/3/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/2/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    2013-03-20 13:18:42,888 INFO
    org.apache.hadoop.hdfs.server.namenode.FSImage: Saving image file
    /data/4/dfs/nn/current/fsimage.ckpt_0000000000000185306 using no compression
    But then decides there are too many? And I have no idea where it is
    getting the numbers 165,186 or 75,814 (as I said, there are 70,130 edits_
    files in the current directory). I don't think any metadata was lost, but
    am not sure.
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857


    --
    Harsh J

    --
    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857




    --
    Todd Lipcon
    Software Engineer, Cloudera

    --

    --
    Dan Bongert dbongert@ssc.wisc.edu
    SSCC Linux System Administrator (608) 262-9857
    --

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupcdh-user @
categorieshadoop
postedMar 20, '13 at 7:03p
activeMar 26, '13 at 5:14p
posts7
users4
websitecloudera.com
irc#hadoop

People

Translate

site design / logo © 2022 Grokbase