Return-Path: Delivered-To: apmail-hadoop-hdfs-user-archive@minotaur.apache.org Received: (qmail 82115 invoked from network); 5 Oct 2010 18:33:15 -0000 Received: from unknown (HELO mail.apache.org) (140.211.11.3) by 140.211.11.9 with SMTP; 5 Oct 2010 18:33:15 -0000 Received: (qmail 99963 invoked by uid 500); 5 Oct 2010 18:33:15 -0000 Delivered-To: apmail-hadoop-hdfs-user-archive@hadoop.apache.org Received: (qmail 99903 invoked by uid 500); 5 Oct 2010 18:33:14 -0000 Mailing-List: contact hdfs-user-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: hdfs-user@hadoop.apache.org Delivered-To: mailing list hdfs-user@hadoop.apache.org Received: (qmail 99895 invoked by uid 99); 5 Oct 2010 18:33:14 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 05 Oct 2010 18:33:14 +0000 X-ASF-Spam-Status: No, hits=2.2 required=10.0 tests=FREEMAIL_FROM,HTML_MESSAGE,NORMAL_HTTP_TO_IP,SPF_PASS,T_TO_NO_BRKTS_FREEMAIL X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: local policy) Received: from [98.139.91.74] (HELO nm4.bullet.mail.sp2.yahoo.com) (98.139.91.74) by apache.org (qpsmtpd/0.29) with SMTP; Tue, 05 Oct 2010 18:33:08 +0000 Received: from [98.139.91.70] by nm4.bullet.mail.sp2.yahoo.com with NNFMP; 05 Oct 2010 18:32:47 -0000 Received: from [98.139.91.19] by tm10.bullet.mail.sp2.yahoo.com with NNFMP; 05 Oct 2010 18:32:47 -0000 Received: from [127.0.0.1] by omp1019.mail.sp2.yahoo.com with NNFMP; 05 Oct 2010 18:32:46 -0000 X-Yahoo-Newman-Property: ymail-3 X-Yahoo-Newman-Id: 949903.3169.bm@omp1019.mail.sp2.yahoo.com Received: (qmail 2556 invoked by uid 60001); 5 Oct 2010 18:32:46 -0000 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yahoo.com; s=s1024; t=1286303566; bh=BgaQsWw8428hrZE7JYDGv1StPlpauHTCpvrZaxlPaZs=; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=RuoE0gZmN2SUcpkyageqEgheL0AAOLrDDSc+p8BNSU6HHZD0Qmb/vVTMSJD29NIJ5p8kw+a/TXjEIohKCGDadCQY7qnptcVoIc/tP/NyagF7aD2cy1FlIh0sIH/iCX5211MDswisnw5wsy1iJekp4BBYP3guwtZHbPdcfq3OR4M= DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=Message-ID:X-YMail-OSG:Received:X-Mailer:References:Date:From:Subject:To:In-Reply-To:MIME-Version:Content-Type; b=OSX2OZ8DSYPF2nFZ4/PAgaWOvFlC74hFdQ85HxsHIetJ6MsWGfqayzwSI9nyM7yCfV4QFygH4J15od0Kva1fu0XexT8jxKZ2wW2VfscHuR+kalhZaEvAt4s5VmuZPXoPtkXyR00GSG2ypYD7tA2QkHG/xP6iQFi7XKGTUBop+Bk=; Message-ID: <131471.2544.qm@web110502.mail.gq1.yahoo.com> X-YMail-OSG: v4OoEn4VM1nw56BUDNy9PTCIKus8E9UZz5UHWf7ZPY6xKnl Ip3cJovaPKWFI7JNGuGxYrRsDOeV_3Oajcu6Z81GPWVt2wP3HLdT8_ZmhuMn w30OSd88hveILQVVYC7kMYdyl_HEgvWP.xPD2FWRlKjjJ_0pmwIWTy7A.egs RYvEGH4.fgN7HpMtHUsP8OIE_qN7lZSx2nkxSDCHKJ48oiBkwqHsQMfJoeKE TBTMXZDGA.cXZfZvcAYeFprGa50KLvO1.XHZx3.XyZACkpHLnbGDU8x2bOoy N09FMae043wo4Gmtl16KzVl5O7ulEA_jnbbexButy5L4ov1pCZCxZAIto_yu 4D_0yIQ84KhrRm7bJw5e3zvh.qTvo Received: from [216.113.168.141] by web110502.mail.gq1.yahoo.com via HTTP; Tue, 05 Oct 2010 11:32:45 PDT X-Mailer: YahooMailRC/504.5 YahooMailWebService/0.8.106.282862 References: <83E09645-A671-4DCE-89A6-D0E1952190A9@mlogiciels.com> <365348B5-B767-4710-873D-BEE239BC4E3D@mlogiciels.com> Date: Tue, 5 Oct 2010 11:32:45 -0700 (PDT) From: Ayon Sinha Subject: Re: NameNode crash - cannot start dfs - need help To: hdfs-user@hadoop.apache.org In-Reply-To: <365348B5-B767-4710-873D-BEE239BC4E3D@mlogiciels.com> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="0-2093550388-1286303565=:2544" --0-2093550388-1286303565=:2544 Content-Type: text/plain; charset=us-ascii Hi Matthew, Congratulations. Having a HDFS back is quite a relief and you were lucky enough to not loose any files/blocks. Another thing I ended up doing was to decommission the namenode machine from being a data node. That is what had caused the namenode to get out of disk space. -Ayon ________________________________ From: Matthew LeMieux To: hdfs-user@hadoop.apache.org Sent: Tue, October 5, 2010 11:25:57 AM Subject: Re: NameNode crash - cannot start dfs - need help Thank you Ayon, Allen and Todd for your suggestions. I was tempted to try to find the offending records in edits.new, but opted for simply moving the file instead. I kept the recently edited edits file in place. The namenode started up this time with no exceptions and appears to be running well; hadoop fsck / reports a healthy filesystem. Thank you, Matthew On Oct 5, 2010, at 10:09 AM, Todd Lipcon wrote: On Tue, Oct 5, 2010 at 9:58 AM, Matthew LeMieux wrote: > >Thank you Todd. >> >> >>It does indeed seem like a challenge to find a record boundary, but if I wanted >>to do it... here is how I did it in case others are interested in doing the >>same. >> >> >> >>It looks like that value (0xFF) is referenced as OP_INVALID in the source file: >>[hadoop-dist]/src//hdfs/org/apache/hadoop/hdfs/server/namenode/FSEditLog.java. >> >> >>Every record begins with an op code that describes the record. The op codes are >>in the range [0,14] (inclusive), except for OP_INVALID. Each record type (based >>on op code) appears to have a different format. Additionally, it seems that the >>code for each record type has several code paths to support different versions >>of the hdfs. >> >> >> I looked in the error messages, and found the line number of the exception >>within the switch statement in the code (in this case, line 563). That told me >>that I was looking for an op code of either 0x00 or 0x09. I noticed that this >>particular code path had a record type that looked like this: >>[# bytes: name] >> >> >>[1:op code][4:int length][2:file system path length][?:file system path text] >> >> >>All I had to do was find a filesystem path, and look 7 bytes before it started. >> If the op code was a 0x00 or 0x09, then this was a candidate record. >> >> >>It would have been easier to just search for something from the error message >>(i.e. "12862" for me) to find candidate records, but in my case that was in >>almost every record. Additionally, it would have also been easier to just >>search for instances of the op code, but in my case one of the op codes (0x00) >>appears too often in the data to make that useful. If your op code is 0x03 for >>example, you will probably have a much easier time of it than I did. >> >> >>I was able to successfully and quickly find record boundaries and replace the op >>code with 0xff. After a few records I was back to the NPE exception that I was >>getting with a zero length edits file: >> >> >>2010-10-05 16:47:39,670 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits >>file /mnt/name/current/edits of size 157037 edits # 959 loaded in 0 seconds. >>2010-10-05 16:47:39,671 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: >>java.lang.NullPointerException >> at >>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1081) >> >> at >>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1093) >> >> at >>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:996) >> at >>org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:199) >> >> at >>org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:627) >> at >>org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022) >> at >>org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:830) >> at >>org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:378) >> >> at >>org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:92) >> >> >> >>One hurdle down, how do I get past the next one? It's unclear whether you're getting the error in "edits" or "edits.new". From the above, I'm guessing maybe "edits" is corrupt, so when you fixed the error there (by truncating a few edits from the end), then the later edits in edits.new failed, because they depended on a path that should have been created by "edits". > >(BTW, what if I didn't want to keep my recent edits, and just wanted to start up >the namenode? This is currently expensive downtime; I'd rather lose a small >amount of data and be up and running than continue the down time). If you really want to do this, you can remove "edits.new", and replace "edits" with a file containing hex 0xffffffeeff I believe (edits header plus OP_INVALID) -Todd Oct 5, 2010, at 8:42 AM, Todd Lipcon wrote: > >Hi Matt, >> >> >>If you want to keep your recent edits, you'll have to place an 0xFF at the >>beginning of the most recent edit entry in the edit log. It's a bit tough to >>find these boundaries, but you can try applying this patch and rebuilding: >> >> >>https://issues.apache.org/jira/browse/hdfs-1378 >> >> >>This will tell you the offset of the broken entry ("recent opcodes") and you can >>put an 0xff there to tie off the file before the corrupt entry. >> >> >>-Todd >> >> >> >> >>On Tue, Oct 5, 2010 at 8:16 AM, Matthew LeMieux wrote: >> >>The namenode on an otherwise very stable HDFS cluster crashed recently. The >>filesystem filled up on the name node, which I assume is what caused the crash. >> The problem has been fixed, but I cannot get the namenode to restart. I am >>using version CDH3b2 (hadoop-0.20.2+320). >>> >>> >>>The error is this: >>> >>> >>>2010-10-05 14:46:55,989 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits >>>file /mnt/name/current/edits of size 157037 edits # 969 loaded in 0 seconds. >>>2010-10-05 14:46:55,992 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: >>>java.lang.NumberFormatException: For input string: "12862^@^@^@^@^@^@^@^@" >>> at >>>java.lang.NumberFormatException.forInputString(NumberFormatException.java:48) >>> at java.lang.Long.parseLong(Long.java:419) >>> at java.lang.Long.parseLong(Long.java:468) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSEditLog.readLong(FSEditLog.java:1355) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:563) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022) >>> ... >>> >>> >>>This page (http://wiki.apache.org/hadoop/TroubleShooting) recommends editing the >>>edits file with a hex editor, but does not explain where the record boundaries >>>are. It is a different exception, but seemed like a similar cause, the edits >>>file. I tried removing a line at a time, but the error continues, only with a >>>smaller size and edits #: >>> >>> >>>2010-10-05 14:37:16,635 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits >>>file /mnt/name/current/edits of size 156663 edits # 966 loaded in 0 seconds. >>>2010-10-05 14:37:16,638 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: >>>java.lang.NumberFormatException: For input string: "12862^@^@^@^@^@^@^@^@" >>> at >>>java.lang.NumberFormatException.forInputString(NumberFormatException.java:48) >>> at java.lang.Long.parseLong(Long.java:419) >>> at java.lang.Long.parseLong(Long.java:468) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSEditLog.readLong(FSEditLog.java:1355) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:563) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022) >>> ... >>> >>> >>>I tried removing the edits file altogether, but that failed >>>with: java.io.IOException: Edits file is not found >>> >>> >>>I tried with a zero length edits file, so it would at least have a file there, >>>but that results in an NPE: >>> >>> >>>2010-10-05 14:52:34,775 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits >>>file /mnt/name/current/edits of size 0 edits # 0 loaded in 0 seconds. >>>2010-10-05 14:52:34,776 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: >>>java.lang.NullPointerException >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1081) >>> >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1093) >>> >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:996) >>> at >>>org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:199) >>> >>> >>> >>> >>> >>>Most if not all the files I noticed in the edits file are temporary files that >>>will be deleted once this thing gets back up and running anyway. There is a >>>closed ticket that might be >>>related: https://issues.apache.org/jira/browse/HDFS-686 , but the version I'm >>>using seems to already have HDFS-686 (according >>>to http://archive.cloudera.com/cdh/3/hadoop-0.20.2+320/changes.html) >>> >>> >>>What do I have to do to get back up and running? >>> >>> >>>Thank you for your help, >>> >>>Matthew >>> >>> >>> >>> >> >> >>-- >>Todd Lipcon >>Software Engineer, Cloudera >> > > > >-- >Todd Lipcon >Software Engineer, Cloudera > --0-2093550388-1286303565=:2544 Content-Type: text/html; charset=us-ascii
Hi Matthew,
Congratulations. Having a HDFS back is quite a relief and you were lucky enough to not loose any files/blocks.
Another thing I ended up doing was to decommission the namenode machine from being a data node. That is what had caused the namenode to get out of disk space. 
 
-Ayon


From: Matthew LeMieux <mdl@mlogiciels.com>
To: hdfs-user@hadoop.apache.org
Sent: Tue, October 5, 2010 11:25:57 AM
Subject: Re: NameNode crash - cannot start dfs - need help

Thank you Ayon, Allen and Todd for your suggestions. 

I was tempted to try to find the offending records in edits.new, but opted for simply moving the file instead.  I kept the recently edited edits file in place. 

The namenode started up this time with no exceptions and appears to be running well;  hadoop fsck / reports a healthy filesystem. 

Thank you, 

Matthew

On Oct 5, 2010, at 10:09 AM, Todd Lipcon wrote:

On Tue, Oct 5, 2010 at 9:58 AM, Matthew LeMieux <mdl@mlogiciels.com> wrote:
Thank you Todd. 

It does indeed seem like a challenge to find a record boundary, but if I wanted to do it...   here is how I did it in case others are interested in doing the same.  

It looks like that value (0xFF) is referenced as OP_INVALID in the source file: [hadoop-dist]/src//hdfs/org/apache/hadoop/hdfs/server/namenode/FSEditLog.java. 

Every record begins with an op code that describes the record.  The op codes are in the range [0,14] (inclusive), except for OP_INVALID.  Each record type (based on op code) appears to have a different format.  Additionally, it seems that the code for each record type has several code paths to support different versions of the hdfs.  

 I looked in the error messages, and found the line number of the exception within the switch statement in the code (in this case, line 563).  That told me that I was looking for an op code of either 0x00 or 0x09.  I noticed that this particular code path had a record type that looked like this: 
[# bytes: name]

[1:op code][4:int length][2:file system path length][?:file system path text]

All I had to do was find a filesystem path, and look 7 bytes before it started.  If the op code was a 0x00 or 0x09, then this was a candidate record. 

It would have been easier to just search for something from the error message (i.e. "12862" for me) to find candidate records, but in my case that was in almost every record.  Additionally, it would have also been easier to just search for instances of the op code, but in my case one of the op codes (0x00) appears too often in the data to make that useful.   If your op code is 0x03 for example, you will probably have a much easier time of it than I did.  

I was able to successfully and quickly find record boundaries and replace the op code with 0xff.  After a few records I was back to the NPE exception that I was getting with a zero length edits file: 

2010-10-05 16:47:39,670 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /mnt/name/current/edits of size 157037 edits # 959 loaded in 0 seconds.
2010-10-05 16:47:39,671 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: java.lang.NullPointerException
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1081)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1093)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:996)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:199)
        at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:627)
        at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022)
        at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:830)
        at org.apache.hadoop.hdfs.server.namenode.FSImage.recoverTransitionRead(FSImage.java:378)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.loadFSImage(FSDirectory.java:92)

One hurdle down, how do I get past the next one?

It's unclear whether you're getting the error in "edits" or "edits.new". From the above, I'm guessing maybe "edits" is corrupt, so when you fixed the error there (by truncating a few edits from the end), then the later edits in edits.new failed, because they depended on a path that should have been created by "edits".

(BTW, what if I didn't want to keep my recent edits, and just wanted to start up the namenode?   This is currently expensive downtime; I'd rather lose a small amount of data and be up and running than continue the down time). 

If you really want to do this, you can remove "edits.new", and replace "edits" with a file containing hex 0xffffffeeff I believe (edits header plus OP_INVALID)

-Todd
 
Oct 5, 2010, at 8:42 AM, Todd Lipcon wrote:

Hi Matt,

If you want to keep your recent edits, you'll have to place an 0xFF at the beginning of the most recent edit entry in the edit log. It's a bit tough to find these boundaries, but you can try applying this patch and rebuilding:


This will tell you the offset of the broken entry ("recent opcodes") and you can put an 0xff there to tie off the file before the corrupt entry.

-Todd


On Tue, Oct 5, 2010 at 8:16 AM, Matthew LeMieux <mdl@mlogiciels.com> wrote:
The namenode on an otherwise very stable HDFS cluster crashed recently.  The filesystem filled up on the name node, which I assume is what caused the crash.    The problem has been fixed, but I cannot get the namenode to restart.  I am using version CDH3b2  (hadoop-0.20.2+320). 

The error is this: 

2010-10-05 14:46:55,989 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /mnt/name/current/edits of size 157037 edits # 969 loaded in 0 seconds.
2010-10-05 14:46:55,992 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: java.lang.NumberFormatException: For input string: "12862^@^@^@^@^@^@^@^@"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48)
        at java.lang.Long.parseLong(Long.java:419)
        at java.lang.Long.parseLong(Long.java:468)
        at org.apache.hadoop.hdfs.server.namenode.FSEditLog.readLong(FSEditLog.java:1355)
        at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:563)
        at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022)
        ...

This page (http://wiki.apache.org/hadoop/TroubleShooting) recommends editing the edits file with a hex editor, but does not explain where the record boundaries are.  It is a different exception, but seemed like a similar cause, the edits file.  I tried removing a line at a time, but the error continues, only with a smaller size and edits #: 

2010-10-05 14:37:16,635 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /mnt/name/current/edits of size 156663 edits # 966 loaded in 0 seconds.
2010-10-05 14:37:16,638 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: java.lang.NumberFormatException: For input string: "12862^@^@^@^@^@^@^@^@"
        at java.lang.NumberFormatException.forInputString(NumberFormatException.java:48)
        at java.lang.Long.parseLong(Long.java:419)
        at java.lang.Long.parseLong(Long.java:468)
        at org.apache.hadoop.hdfs.server.namenode.FSEditLog.readLong(FSEditLog.java:1355)
        at org.apache.hadoop.hdfs.server.namenode.FSEditLog.loadFSEdits(FSEditLog.java:563)
        at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSEdits(FSImage.java:1022)
        ...

I tried removing the edits file altogether, but that failed with: java.io.IOException: Edits file is not found

I tried with a zero length edits file, so it would at least have a file there, but that results in an NPE: 

2010-10-05 14:52:34,775 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /mnt/name/current/edits of size 0 edits # 0 loaded in 0 seconds.
2010-10-05 14:52:34,776 ERROR org.apache.hadoop.hdfs.server.namenode.NameNode: java.lang.NullPointerException
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1081)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addChild(FSDirectory.java:1093)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.addNode(FSDirectory.java:996)
        at org.apache.hadoop.hdfs.server.namenode.FSDirectory.unprotectedAddFile(FSDirectory.java:199)


Most if not all the files I noticed in the edits file are temporary files that will be deleted once this thing gets back up and running anyway.    There is a closed ticket that might be related: https://issues.apache.org/jira/browse/HDFS-686 ,  but the version I'm using seems to already have HDFS-686 (according to http://archive.cloudera.com/cdh/3/hadoop-0.20.2+320/changes.html)  

What do I have to do to get back up and running?

Thank you for your help, 

Matthew





--
Todd Lipcon
Software Engineer, Cloudera




--
Todd Lipcon
Software Engineer, Cloudera


--0-2093550388-1286303565=:2544--