Hadoop HDFS
  1. Hadoop HDFS
  2. HDFS-1024

SecondaryNamenode fails to checkpoint because namenode fails with CancelledKeyException

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 0.20.1, 0.20.2, 0.20.3, 0.21.0, 0.22.0
    • Fix Version/s: 0.21.0
    • Component/s: None
    • Labels:
      None
    • Hadoop Flags:
      Incompatible change

      Description

      The secondary namenode fails to retrieve the entire fsimage from the Namenode. It fetches a part of the fsimage but believes that it has fetched the entire fsimage file and proceeds ahead with the checkpointing. Stack traces will be attached below.

      1. HDFS-1024.patch.1-0.20.txt
        6 kB
        stack
      2. HDFS-1024.patch.1
        6 kB
        Dmytro Molkov
      3. HDFS-1024.patch
        6 kB
        Dmytro Molkov

        Issue Links

          Activity

          Hide
          dhruba borthakur added a comment -

          The namenode logs show the following:

          WARN org.mortbay.log: Committed before 410 GetImage failed. java.nio.channels.CancelledKeyException
          at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
          at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
          at org.mortbay.io.nio.SelectChannelEndPoint.updateKey(SelectChannelEndPoint.java:324)
          at org.mortbay.io.nio.SelectChannelEndPoint.blockWritable(SelectChannelEndPoint.java:278)
          at org.mortbay.jetty.AbstractGenerator$Output.blockForOutput(AbstractGenerator.java:542)
          at org.mortbay.jetty.AbstractGenerator$Output.flush(AbstractGenerator.java:569)
          at org.mortbay.jetty.HttpConnection$Output.flush(HttpConnection.java:946)
          at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:646)
          at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:577)
          at org.apache.hadoop.hdfs.server.namenode.TransferFsImage.getFileServer(TransferFsImage.java:127)
          at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:49)
          at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
          at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
          at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
          at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
          at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
          at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
          at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
          at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
          at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
          at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
          at org.mortbay.jetty.Server.handle(Server.java:324)
          at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
          at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
          at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
          at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
          at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
          at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
          at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
          

          The secondary namenode logs show that it believes that the fsimage is only about 2 GB. It does not detect the case that the transfer of the fsimage file was incomplete.

          2010-03-03 23:33:05,598 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 2337800192 bytes.
          2010-03-03 23:38:50,550 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 254702213 bytes.
          
          Show
          dhruba borthakur added a comment - The namenode logs show the following: WARN org.mortbay.log: Committed before 410 GetImage failed. java.nio.channels.CancelledKeyException at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55) at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59) at org.mortbay.io.nio.SelectChannelEndPoint.updateKey(SelectChannelEndPoint.java:324) at org.mortbay.io.nio.SelectChannelEndPoint.blockWritable(SelectChannelEndPoint.java:278) at org.mortbay.jetty.AbstractGenerator$Output.blockForOutput(AbstractGenerator.java:542) at org.mortbay.jetty.AbstractGenerator$Output.flush(AbstractGenerator.java:569) at org.mortbay.jetty.HttpConnection$Output.flush(HttpConnection.java:946) at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:646) at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:577) at org.apache.hadoop.hdfs.server.namenode.TransferFsImage.getFileServer(TransferFsImage.java:127) at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:49) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766) at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417) at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:324) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522) The secondary namenode logs show that it believes that the fsimage is only about 2 GB. It does not detect the case that the transfer of the fsimage file was incomplete. 2010-03-03 23:33:05,598 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 2337800192 bytes. 2010-03-03 23:38:50,550 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 254702213 bytes.
          Hide
          dhruba borthakur added a comment -

          In the above case, the size of the actual fsimage was more than 8 GB. The secondary pulled in only 2.33 GB of that file.

          Show
          dhruba borthakur added a comment - In the above case, the size of the actual fsimage was more than 8 GB. The secondary pulled in only 2.33 GB of that file.
          Hide
          dhruba borthakur added a comment -

          One proposal to fix this issue is that the CheckpointSignature returned by rollEditLogs() method should include the size of the fsimage. Then the secondaryNN can validate that the size of the fsimage file that it downloaded from the NN matches the value stored in the CheckpointSignature.

          Show
          dhruba borthakur added a comment - One proposal to fix this issue is that the CheckpointSignature returned by rollEditLogs() method should include the size of the fsimage. Then the secondaryNN can validate that the size of the fsimage file that it downloaded from the NN matches the value stored in the CheckpointSignature.
          Hide
          Todd Lipcon added a comment -

          Does the servlet not set a Content-length HTTP header? Since we're using HTTP we might as well include it there. Then the HTTP client can easily verify it without having to modify CheckpointSignature

          Show
          Todd Lipcon added a comment - Does the servlet not set a Content-length HTTP header? Since we're using HTTP we might as well include it there. Then the HTTP client can easily verify it without having to modify CheckpointSignature
          Hide
          Dmytro Molkov added a comment -

          Since the image file can bee too long sometimes Content-Length is not set, instead it sets Transfer-Encoding: chunked
          I am setting Content-Length manually in the servlet now.
          One thing to note here, there is a response.setContentLength(int) method, but taking int as a parameter it will not work, since many images are over 2Gb in size. So I am setting it as a general HTTP header.

          On the client side once the read is over we check if the number of bytes we read is equal to advertised in the Content-Length and throw if it is not.

          Show
          Dmytro Molkov added a comment - Since the image file can bee too long sometimes Content-Length is not set, instead it sets Transfer-Encoding: chunked I am setting Content-Length manually in the servlet now. One thing to note here, there is a response.setContentLength(int) method, but taking int as a parameter it will not work, since many images are over 2Gb in size. So I am setting it as a general HTTP header. On the client side once the read is over we check if the number of bytes we read is equal to advertised in the Content-Length and throw if it is not.
          Hide
          Dmytro Molkov added a comment -

          Note though, that this patch doesn't fix the underlying issue (that might as well be a jetty but of sending huge images) and only protects HDFS from corrupting the image in the case when the partial image read will be valid and will substitute the current image after secondary name node processes it.

          Show
          Dmytro Molkov added a comment - Note though, that this patch doesn't fix the underlying issue (that might as well be a jetty but of sending huge images) and only protects HDFS from corrupting the image in the case when the partial image read will be valid and will substitute the current image after secondary name node processes it.
          Hide
          Dmytro Molkov added a comment -

          Todd, can you have a look at this patch using the approach of Content-Length header? Thanks!

          Show
          Dmytro Molkov added a comment - Todd, can you have a look at this patch using the approach of Content-Length header? Thanks!
          Hide
          Todd Lipcon added a comment -

          Hi Dmytro,

          A few comments:

          • in the test, rather than assertTrue(false) can you use fail("Did not get expected exception")?
          • perhaps add a String constant for "Content-Length'
          • Do we care about getFileClient() working against a server that may not provide the Content-Length header? We may want to at least fail with a better error message (instead of NPE or NFE) if the header is not present. Alternatively, we could issue a WARN and just disable this check if the header is not present.
          • The error message and the variable name "imageName" imply that it's always the fsImage being transferred. The same code path is used to download the edits. Perhaps best to include the URL in the exception message?

          Thanks
          -Todd

          Show
          Todd Lipcon added a comment - Hi Dmytro, A few comments: in the test, rather than assertTrue(false) can you use fail("Did not get expected exception")? perhaps add a String constant for "Content-Length' Do we care about getFileClient() working against a server that may not provide the Content-Length header? We may want to at least fail with a better error message (instead of NPE or NFE) if the header is not present. Alternatively, we could issue a WARN and just disable this check if the header is not present. The error message and the variable name "imageName" imply that it's always the fsImage being transferred. The same code path is used to download the edits. Perhaps best to include the URL in the exception message? Thanks -Todd
          Hide
          Dmytro Molkov added a comment -

          Please see the new patch with your comments addressed.
          It seems like throwing an exception with a meaningful text is the way to go for a couple of reasons: you would not really run SecondaryNameNode and the NameNode of different versions (or at least you shouldn't).
          And with the check disabled there is a room for image corruption, which should never be the case.

          Show
          Dmytro Molkov added a comment - Please see the new patch with your comments addressed. It seems like throwing an exception with a meaningful text is the way to go for a couple of reasons: you would not really run SecondaryNameNode and the NameNode of different versions (or at least you shouldn't). And with the check disabled there is a room for image corruption, which should never be the case.
          Hide
          Todd Lipcon added a comment -

          lgtm, thanks for those changes. should of course run this through Hudson as well.

          Show
          Todd Lipcon added a comment - lgtm, thanks for those changes. should of course run this through Hudson as well.
          Hide
          Hadoop QA added a comment -

          -1 overall. Here are the results of testing the latest attachment
          http://issues.apache.org/jira/secure/attachment/12438567/HDFS-1024.patch.1
          against trunk revision 921697.

          +1 @author. The patch does not contain any @author tags.

          +1 tests included. The patch appears to include 3 new or modified tests.

          +1 javadoc. The javadoc tool did not generate any warning messages.

          +1 javac. The applied patch does not increase the total number of javac compiler warnings.

          +1 findbugs. The patch does not introduce any new Findbugs warnings.

          +1 release audit. The applied patch does not increase the total number of release audit warnings.

          +1 core tests. The patch passed core unit tests.

          -1 contrib tests. The patch failed contrib unit tests.

          Test results: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/testReport/
          Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
          Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/artifact/trunk/build/test/checkstyle-errors.html
          Console output: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/console

          This message is automatically generated.

          Show
          Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12438567/HDFS-1024.patch.1 against trunk revision 921697. +1 @author. The patch does not contain any @author tags. +1 tests included. The patch appears to include 3 new or modified tests. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. +1 core tests. The patch passed core unit tests. -1 contrib tests. The patch failed contrib unit tests. Test results: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/testReport/ Findbugs warnings: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Checkstyle results: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/artifact/trunk/build/test/checkstyle-errors.html Console output: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/267/console This message is automatically generated.
          Hide
          Dmytro Molkov added a comment -

          It seems like the failure is
          Failed to download http://apache.osuosl.org/tomcat/tomcat-6/v6.0.18/bin/apache-tomcat-6.0.18.zip

          Should I resubmit the patch so the tests can run again?

          Show
          Dmytro Molkov added a comment - It seems like the failure is Failed to download http://apache.osuosl.org/tomcat/tomcat-6/v6.0.18/bin/apache-tomcat-6.0.18.zip Should I resubmit the patch so the tests can run again?
          Hide
          Jakob Homan added a comment -

          Dmytro-
          No need to resubmit, this is a known issue.

          Show
          Jakob Homan added a comment - Dmytro- No need to resubmit, this is a known issue.
          Hide
          dhruba borthakur added a comment -

          +1 code looks good.

          Show
          dhruba borthakur added a comment - +1 code looks good.
          Hide
          Dmytro Molkov added a comment -

          Can anyone commit this?

          Show
          Dmytro Molkov added a comment - Can anyone commit this?
          Hide
          stack added a comment -

          I will commit this issue in next day or so unless objection or unless someone else beats me to it. IMO, this issue is a blocker as it can corrupt fsimage.

          We just ran into this issue except the faliure was in the transfer from 2NN to NN. Only a partial copy was done because we ran into a CancelledKeyException. Thereafter our fsimage is corrupt. Subsequent 2NN copies of image all fail because they fail to read the mangled image.

          Here's the evidence.

          This is the 2NN log from just before the CancelledKeyException.

          2010-03-28 00:43:28,173 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 9220979 bytes.
          2010-03-28 00:43:28,202 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 3190207 bytes.
          2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop
          2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup
          2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true
          2010-03-28 00:43:28,291 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64126
          2010-03-28 00:43:29,016 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files under construction = 15
          2010-03-28 00:43:29,510 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /export/hadoop/dfs/namesecondary/current/edits of size 3190207 edits # 30862 loaded in 0 seconds.
          2010-03-28 00:43:29,754 INFO org.apache.hadoop.hdfs.server.common.Storage: Image file of size 9244565 saved in 0 seconds.
          2010-03-28 00:43:29,922 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0
          2010-03-28 00:43:30,058 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Posted URL 10.10.20.221:50070putimage=1&port=50090&machine=10.10.20.222&token=-18:996348214:1231385509605:1269762207000:1269758607364
          2010-03-28 00:43:37,514 WARN org.mortbay.log: Committed before 410 GetImage failed. java.nio.channels.CancelledKeyException
                  at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55)
                  at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59)
                  at org.mortbay.io.nio.SelectChannelEndPoint.updateKey(SelectChannelEndPoint.java:324)
                  at org.mortbay.io.nio.SelectChannelEndPoint.blockWritable(SelectChannelEndPoint.java:278)
                  at org.mortbay.jetty.AbstractGenerator$Output.blockForOutput(AbstractGenerator.java:542)
                  at org.mortbay.jetty.AbstractGenerator$Output.flush(AbstractGenerator.java:569)
                  at org.mortbay.jetty.HttpConnection$Output.flush(HttpConnection.java:946)
                  at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:646)
                  at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:577)
                  at org.apache.hadoop.hdfs.server.namenode.TransferFsImage.getFileServer(TransferFsImage.java:127)
                  at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:49)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
                  at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
                  at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
                  at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
                  at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
                  at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
                  at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
                  at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
                  at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
                  at org.mortbay.jetty.Server.handle(Server.java:324)
                  at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
                  at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
                  at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
                  at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
                  at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
                  at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
                  at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
          
          2010-03-28 00:43:37,516 ERROR org.mortbay.log: /getimage
          java.lang.IllegalStateException: Committed
                  at org.mortbay.jetty.Response.resetBuffer(Response.java:994)
                  at org.mortbay.jetty.Response.sendError(Response.java:240)
                  at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:64)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
                  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
                  at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
                  at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363)
                  at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
                  at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
                  at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
                  at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)
                  at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)
                  at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
                  at org.mortbay.jetty.Server.handle(Server.java:324)
                  at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534)
                  at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864)
                  at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533)
                  at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207)
                  at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403)
                  at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
                  at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)
          2010-03-28 00:43:37,724 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 9244565
          2010-03-28 01:43:37,747 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 
          2010-03-28 01:43:38,159 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 4521984 bytes.
          2010-03-28 01:43:38,184 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 2745394 bytes.
          2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop
          2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup
          2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true
          2010-03-28 01:43:38,264 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64295
          2010-03-28 01:43:38,613 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Exception in doCheckpoint: 
          2010-03-28 01:43:38,613 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.io.EOFException
                  at java.io.DataInputStream.readFully(DataInputStream.java:180)
                  at java.io.DataInputStream.readLong(DataInputStream.java:399)
                  at org.apache.hadoop.hdfs.protocol.Block.readFields(Block.java:136)
                  at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:904)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:589)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:473)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:350)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:314)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:225)
                  at java.lang.Thread.run(Thread.java:619)
          
          2010-03-28 01:48:38,622 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 
          2010-03-28 01:48:38,651 INFO org.apache.hadoop.hdfs.server.common.Storage: Recovering storage directory /export/hadoop/dfs/namesecondary from failed checkpoint.
          2010-03-28 01:48:38,696 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 4521984 bytes.
          2010-03-28 01:48:38,721 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 2745394 bytes.
          2010-03-28 01:48:38,804 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop
          2010-03-28 01:48:38,805 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup
          2010-03-28 01:48:38,805 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled=true
          2010-03-28 01:48:38,806 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64295
          2010-03-28 01:48:39,173 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Exception in doCheckpoint: 
          2010-03-28 01:48:39,174 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.io.EOFException
                  at java.io.DataInputStream.readFully(DataInputStream.java:180)
                  at java.io.DataInputStream.readLong(DataInputStream.java:399)
                  at org.apache.hadoop.hdfs.protocol.Block.readFields(Block.java:136)
                  at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:904)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:589)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:473)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:350)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:314)
                  at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:225)
                  at java.lang.Thread.run(Thread.java:619)
          ....
          

          And so on.

          I don't see log of NN-side of things. We were not running with DEBUG enabled.

          Show
          stack added a comment - I will commit this issue in next day or so unless objection or unless someone else beats me to it. IMO, this issue is a blocker as it can corrupt fsimage. We just ran into this issue except the faliure was in the transfer from 2NN to NN. Only a partial copy was done because we ran into a CancelledKeyException. Thereafter our fsimage is corrupt. Subsequent 2NN copies of image all fail because they fail to read the mangled image. Here's the evidence. This is the 2NN log from just before the CancelledKeyException. 2010-03-28 00:43:28,173 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 9220979 bytes. 2010-03-28 00:43:28,202 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 3190207 bytes. 2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop 2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup 2010-03-28 00:43:28,288 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled= true 2010-03-28 00:43:28,291 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64126 2010-03-28 00:43:29,016 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files under construction = 15 2010-03-28 00:43:29,510 INFO org.apache.hadoop.hdfs.server.common.Storage: Edits file /export/hadoop/dfs/namesecondary/current/edits of size 3190207 edits # 30862 loaded in 0 seconds. 2010-03-28 00:43:29,754 INFO org.apache.hadoop.hdfs.server.common.Storage: Image file of size 9244565 saved in 0 seconds. 2010-03-28 00:43:29,922 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 2010-03-28 00:43:30,058 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Posted URL 10.10.20.221:50070putimage=1&port=50090&machine=10.10.20.222&token=-18:996348214:1231385509605:1269762207000:1269758607364 2010-03-28 00:43:37,514 WARN org.mortbay.log: Committed before 410 GetImage failed. java.nio.channels.CancelledKeyException at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:55) at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:59) at org.mortbay.io.nio.SelectChannelEndPoint.updateKey(SelectChannelEndPoint.java:324) at org.mortbay.io.nio.SelectChannelEndPoint.blockWritable(SelectChannelEndPoint.java:278) at org.mortbay.jetty.AbstractGenerator$Output.blockForOutput(AbstractGenerator.java:542) at org.mortbay.jetty.AbstractGenerator$Output.flush(AbstractGenerator.java:569) at org.mortbay.jetty.HttpConnection$Output.flush(HttpConnection.java:946) at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:646) at org.mortbay.jetty.AbstractGenerator$Output.write(AbstractGenerator.java:577) at org.apache.hadoop.hdfs.server.namenode.TransferFsImage.getFileServer(TransferFsImage.java:127) at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:49) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766) at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417) at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:324) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522) 2010-03-28 00:43:37,516 ERROR org.mortbay.log: /getimage java.lang.IllegalStateException: Committed at org.mortbay.jetty.Response.resetBuffer(Response.java:994) at org.mortbay.jetty.Response.sendError(Response.java:240) at org.apache.hadoop.hdfs.server.namenode.GetImageServlet.doGet(GetImageServlet.java:64) at javax.servlet.http.HttpServlet.service(HttpServlet.java:707) at javax.servlet.http.HttpServlet.service(HttpServlet.java:820) at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502) at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:363) at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216) at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181) at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766) at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417) at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230) at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152) at org.mortbay.jetty.Server.handle(Server.java:324) at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:534) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:864) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:533) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:207) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:403) at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522) 2010-03-28 00:43:37,724 WARN org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Checkpoint done. New Image Size: 9244565 2010-03-28 01:43:37,747 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 2010-03-28 01:43:38,159 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 4521984 bytes. 2010-03-28 01:43:38,184 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 2745394 bytes. 2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop 2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup 2010-03-28 01:43:38,262 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled= true 2010-03-28 01:43:38,264 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64295 2010-03-28 01:43:38,613 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Exception in doCheckpoint: 2010-03-28 01:43:38,613 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.io.EOFException at java.io.DataInputStream.readFully(DataInputStream.java:180) at java.io.DataInputStream.readLong(DataInputStream.java:399) at org.apache.hadoop.hdfs.protocol.Block.readFields(Block.java:136) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:904) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:589) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:473) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:350) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:314) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:225) at java.lang. Thread .run( Thread .java:619) 2010-03-28 01:48:38,622 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Number of transactions: 0 Total time for transactions(ms): 0Number of transactions batched in Syncs: 0 Number of syncs: 0 SyncTimes(ms): 0 2010-03-28 01:48:38,651 INFO org.apache.hadoop.hdfs.server.common.Storage: Recovering storage directory /export/hadoop/dfs/namesecondary from failed checkpoint. 2010-03-28 01:48:38,696 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file fsimage size 4521984 bytes. 2010-03-28 01:48:38,721 INFO org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Downloaded file edits size 2745394 bytes. 2010-03-28 01:48:38,804 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: fsOwner=hadoop,hadoop 2010-03-28 01:48:38,805 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: supergroup=supergroup 2010-03-28 01:48:38,805 INFO org.apache.hadoop.hdfs.server.namenode.FSNamesystem: isPermissionEnabled= true 2010-03-28 01:48:38,806 INFO org.apache.hadoop.hdfs.server.common.Storage: Number of files = 64295 2010-03-28 01:48:39,173 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: Exception in doCheckpoint: 2010-03-28 01:48:39,174 ERROR org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode: java.io.EOFException at java.io.DataInputStream.readFully(DataInputStream.java:180) at java.io.DataInputStream.readLong(DataInputStream.java:399) at org.apache.hadoop.hdfs.protocol.Block.readFields(Block.java:136) at org.apache.hadoop.hdfs.server.namenode.FSImage.loadFSImage(FSImage.java:904) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.doMerge(SecondaryNameNode.java:589) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode$CheckpointStorage.access$000(SecondaryNameNode.java:473) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doMerge(SecondaryNameNode.java:350) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.doCheckpoint(SecondaryNameNode.java:314) at org.apache.hadoop.hdfs.server.namenode.SecondaryNameNode.run(SecondaryNameNode.java:225) at java.lang. Thread .run( Thread .java:619) .... And so on. I don't see log of NN-side of things. We were not running with DEBUG enabled.
          Hide
          stack added a comment -

          Marking this as a blocker since we would have lost half our hdfs only for our having a backup. Also making this as fix for 0.20.3 hadoop.

          Show
          stack added a comment - Marking this as a blocker since we would have lost half our hdfs only for our having a backup. Also making this as fix for 0.20.3 hadoop.
          Hide
          Cosmin Lehene added a comment -

          Adding effected versions

          Show
          Cosmin Lehene added a comment - Adding effected versions
          Hide
          dhruba borthakur added a comment -

          +1 code looks good.

          Show
          dhruba borthakur added a comment - +1 code looks good.
          Hide
          dhruba borthakur added a comment -

          I committed this for trunk. Thanks Dmytro!

          If we need this for 0.20 branch, can somebody pl upload a patch for the 0.20 branch as well?

          Show
          dhruba borthakur added a comment - I committed this for trunk. Thanks Dmytro! If we need this for 0.20 branch, can somebody pl upload a patch for the 0.20 branch as well?
          Hide
          stack added a comment -

          A patch for 0.20.

          There doesn't seem to be any reason why 0.20 doesn't have the same issue (and so in 0.20 the 2NN could hand back half an fsimage).

          Testing the patch now. Will reporrt if all passes.

          Show
          stack added a comment - A patch for 0.20. There doesn't seem to be any reason why 0.20 doesn't have the same issue (and so in 0.20 the 2NN could hand back half an fsimage). Testing the patch now. Will reporrt if all passes.
          Hide
          stack added a comment -

          All tests pass but the expected fail of: "org.apache.hadoop.streaming.TestStreamingExitStatus"

          I'd like to commit to 0.20 branch. Do we have to run a vote or is evidence of corruption of fsimage enough of a reason?

          Show
          stack added a comment - All tests pass but the expected fail of: "org.apache.hadoop.streaming.TestStreamingExitStatus" I'd like to commit to 0.20 branch. Do we have to run a vote or is evidence of corruption of fsimage enough of a reason?
          Hide
          Todd Lipcon added a comment -

          Not sure if we need a vote, but I do think we should put it in the branch.

          Show
          Todd Lipcon added a comment - Not sure if we need a vote, but I do think we should put it in the branch.
          Hide
          dhruba borthakur added a comment -

          I am going to commit it to 0.20 branch now.

          Show
          dhruba borthakur added a comment - I am going to commit it to 0.20 branch now.
          Hide
          dhruba borthakur added a comment -

          This is actually an incompatible change. So, I have not yet checked it in. If you run a SecondaryNameNode with this patch against a NameNode that does not have this patch, then checkpointing will fail.

          Show
          dhruba borthakur added a comment - This is actually an incompatible change. So, I have not yet checked it in. If you run a SecondaryNameNode with this patch against a NameNode that does not have this patch, then checkpointing will fail.
          Hide
          stack added a comment -

          Well spotted Dhruba.

          So, the scenario is an updated 2NN but NN has not been updated (or vice-versa)? My guess would be that the incidence of NNs not being updated in tandem is low to zero. If this is true, would a release note to the effect that both NNs must be updated together be patch enough to cover the low incidence of encounters of this incompatible change?

          Show
          stack added a comment - Well spotted Dhruba. So, the scenario is an updated 2NN but NN has not been updated (or vice-versa)? My guess would be that the incidence of NNs not being updated in tandem is low to zero. If this is true, would a release note to the effect that both NNs must be updated together be patch enough to cover the low incidence of encounters of this incompatible change?
          Hide
          dhruba borthakur added a comment -

          Stack, I agree with your observation. Can you pl run a vote in the hdfs-dev@ list, just for the records?

          Show
          dhruba borthakur added a comment - Stack, I agree with your observation. Can you pl run a vote in the hdfs-dev@ list, just for the records?
          Hide
          Hudson added a comment -

          Integrated in Hadoop-Hdfs-trunk-Commit #229 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk-Commit/229/)

          Show
          Hudson added a comment - Integrated in Hadoop-Hdfs-trunk-Commit #229 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk-Commit/229/ )
          Hide
          Hudson added a comment -

          Integrated in Hdfs-Patch-h2.grid.sp2.yahoo.net #146 (See http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h2.grid.sp2.yahoo.net/146/)

          Show
          Hudson added a comment - Integrated in Hdfs-Patch-h2.grid.sp2.yahoo.net #146 (See http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h2.grid.sp2.yahoo.net/146/ )
          Hide
          stack added a comment -

          I ran vote up on hdfs-dev as per Dhruba suggestion: http://www.mail-archive.com/hdfs-dev@hadoop.apache.org/msg00930.html. Vote passed with +7 votes. I just committed HDFS-1024.patch.1-0.20.txt to branch-0.20.

          Show
          stack added a comment - I ran vote up on hdfs-dev as per Dhruba suggestion: http://www.mail-archive.com/hdfs-dev@hadoop.apache.org/msg00930.html . Vote passed with +7 votes. I just committed HDFS-1024 .patch.1-0.20.txt to branch-0.20.
          Hide
          Hudson added a comment -

          Integrated in Hdfs-Patch-h5.grid.sp2.yahoo.net #302 (See http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/302/)

          Show
          Hudson added a comment - Integrated in Hdfs-Patch-h5.grid.sp2.yahoo.net #302 (See http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-h5.grid.sp2.yahoo.net/302/ )
          Hide
          Hudson added a comment -

          Integrated in Hadoop-Hdfs-trunk #275 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/275/)

          Show
          Hudson added a comment - Integrated in Hadoop-Hdfs-trunk #275 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/275/ )

            People

            • Assignee:
              Dmytro Molkov
              Reporter:
              dhruba borthakur
            • Votes:
              0 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development