Hadoop HDFS
  1. Hadoop HDFS
  2. HDFS-119

logSync() may block NameNode forever.

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 0.21.0, 1.0.3
    • Component/s: namenode
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      Description

      1. FSEditLog.logSync() first waits until isSyncRunning is false and then performs syncing to file streams by calling EditLogOutputStream.flush().
        If an exception is thrown after isSyncRunning is set to true all threads will always wait on this condition.
        An IOException may be thrown by EditLogOutputStream.setReadyToFlush() or a RuntimeException may be thrown by EditLogOutputStream.flush() or by processIOError().
      2. The loop that calls eStream.flush() for multiple EditLogOutputStream-s is not synchronized, which means that another thread may encounter an error and modify editStreams by say calling processIOError(). Then the iterating process in logSync() will break with IndexOutOfBoundException.
      1. HDFS119.branch1.0.patch
        5 kB
        Brandon Li
      2. HDFS-119.patch
        8 kB
        Suresh Srinivas
      3. HDFS-119.patch
        7 kB
        Suresh Srinivas
      4. HDFS-119-branch-1.0.patch
        5 kB
        Konstantin Shvachko
      5. HDFS-119-branch-1.0.patch
        3 kB
        Konstantin Shvachko

        Issue Links

          Activity

          Konstantin Shvachko created issue -
          Konstantin Shvachko made changes -
          Field Original Value New Value
          Component/s dfs [ 12310710 ]
          Konstantin Shvachko made changes -
          Link This issue is related to HADOOP-4045 [ HADOOP-4045 ]
          Hide
          Tsz Wo Nicholas Sze added a comment -

          Got a NPE in EditLogBackupOutputStream.flushAndSync(..):

          2009-03-24 17:56:09,750 INFO  ipc.Server (Server.java:run(968)) - IPC Server handler 6 on 1441, call startCheckpoint(
          NamenodeRegistration(xx.xx.xx.xx:50100, role=Backup Node)) from 127.0.0.1:1485: error: java.io.IOException: java.lang.NullPointerException
          java.io.IOException: java.lang.NullPointerException
          	at org.apache.hadoop.hdfs.server.namenode.EditLogBackupOutputStream.flushAndSync(EditLogBackupOutputStream.java:163)
          	at org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:83)
          	at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:989)
          	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startCheckpoint(FSNamesystem.java:4395)
          	at org.apache.hadoop.hdfs.server.namenode.NameNode.startCheckpoint(NameNode.java:440)
          	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
          	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
          	at java.lang.reflect.Method.invoke(Method.java:597)
          	at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:508)
          	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:959)
          	at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:955)
          	at java.security.AccessController.doPrivileged(Native Method)
          	at javax.security.auth.Subject.doAs(Subject.java:396)
          	at org.apache.hadoop.ipc.Server$Handler.run(Server.java:953)
          
          Show
          Tsz Wo Nicholas Sze added a comment - Got a NPE in EditLogBackupOutputStream.flushAndSync(..): 2009-03-24 17:56:09,750 INFO ipc.Server (Server.java:run(968)) - IPC Server handler 6 on 1441, call startCheckpoint( NamenodeRegistration(xx.xx.xx.xx:50100, role=Backup Node)) from 127.0.0.1:1485: error: java.io.IOException: java.lang.NullPointerException java.io.IOException: java.lang.NullPointerException at org.apache.hadoop.hdfs.server.namenode.EditLogBackupOutputStream.flushAndSync(EditLogBackupOutputStream.java:163) at org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:83) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:989) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startCheckpoint(FSNamesystem.java:4395) at org.apache.hadoop.hdfs.server.namenode.NameNode.startCheckpoint(NameNode.java:440) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:508) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:959) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:955) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:396) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:953)
          Tsz Wo Nicholas Sze made changes -
          Link This issue relates to HADOOP-5573 [ HADOOP-5573 ]
          Hide
          Tsz Wo Nicholas Sze added a comment -

          The NPE I mentioned above seems a different issue. Created HADOOP-5573.

          Show
          Tsz Wo Nicholas Sze added a comment - The NPE I mentioned above seems a different issue. Created HADOOP-5573 .
          Owen O'Malley made changes -
          Project Hadoop Common [ 12310240 ] HDFS [ 12310942 ]
          Key HADOOP-5510 HDFS-119
          Affects Version/s 0.14.0 [ 12312474 ]
          Component/s dfs [ 12310710 ]
          Hide
          Suresh Srinivas added a comment -

          Along with the problem mentioned in the bug, there are several findbugs associated with unsynchronized access to FSEditlog.editStreams:
          IS Inconsistent synchronization of org.apache.hadoop.hdfs.server.namenode.FSEditLog.editStreams; locked 50% of time

          The attached patch synchronizes access to editStreams. It also makes the following changes:

          1. FSEditLog.logSync() uses try-finally block to ensure isSyncRunning is set to false on encountering exceptions.
          2. FSEditLog.logSync() calls flush on a list of EditLogOutputStream built from editStreams, instead of holding lock against editStreams and preventing other threads from accessing it.
          Show
          Suresh Srinivas added a comment - Along with the problem mentioned in the bug, there are several findbugs associated with unsynchronized access to FSEditlog.editStreams : IS Inconsistent synchronization of org.apache.hadoop.hdfs.server.namenode.FSEditLog.editStreams; locked 50% of time The attached patch synchronizes access to editStreams . It also makes the following changes: FSEditLog.logSync() uses try-finally block to ensure isSyncRunning is set to false on encountering exceptions. FSEditLog.logSync() calls flush on a list of EditLogOutputStream built from editStreams , instead of holding lock against editStreams and preventing other threads from accessing it.
          Suresh Srinivas made changes -
          Attachment HDFS-119.patch [ 12414674 ]
          Hide
          Suresh Srinivas added a comment -

          While running junit tests, the following tests fail, which are unrelated to this patch:
          org.apache.hadoop.hdfs.TestDFSShell
          org.apache.hadoop.hdfs.TestHDFSServerPorts
          org.apache.hadoop.hdfs.server.namenode.TestStartup

          Show
          Suresh Srinivas added a comment - While running junit tests, the following tests fail, which are unrelated to this patch: org.apache.hadoop.hdfs.TestDFSShell org.apache.hadoop.hdfs.TestHDFSServerPorts org.apache.hadoop.hdfs.server.namenode.TestStartup
          Suresh Srinivas made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Konstantin Shvachko added a comment -
          1. You do not need to enclose processIOError() in synchronized section, because it is already synchronized.
          2. getEditsStream() is declared public. Could you please make it package private.
          3. could you please do the same for getStorage().
          4. listEditsStreams() is not used anywhere. Can we just remove it instead of synchronizing.
          Show
          Konstantin Shvachko added a comment - You do not need to enclose processIOError() in synchronized section, because it is already synchronized. getEditsStream() is declared public. Could you please make it package private. could you please do the same for getStorage() . listEditsStreams() is not used anywhere. Can we just remove it instead of synchronizing.
          Suresh Srinivas made changes -
          Assignee Suresh Srinivas [ sureshms ]
          Hide
          Suresh Srinivas added a comment -

          New patch incorporates Konstantin's comment.

          Ran some manual tests by running TestBackupNode test with break points in FSEditLog.logSync() and ensured that isSyncRunning is set to false at the end of the method, as intended.

          All the unit tests passed. Here is the result of test-patch:

          [exec] -1 overall.
          [exec]
          [exec] +1 @author. The patch does not contain any @author tags.
          [exec]
          [exec] -1 tests included. The patch doesn't appear to include any new or modified tests.
          [exec] Please justify why no new tests are needed for this patch.
          [exec] Also please list what manual steps were performed to verify this patch.
          [exec]
          [exec] +1 javadoc. The javadoc tool did not generate any warning messages.
          [exec]
          [exec] +1 javac. The applied patch does not increase the total number of javac compiler warnings.
          [exec]
          [exec] +1 findbugs. The patch does not introduce any new Findbugs warnings.
          [exec]
          [exec] +1 release audit. The applied patch does not increase the total number of release audit warnings.

          No new tests added as existing tests already cover this functionality.

          Show
          Suresh Srinivas added a comment - New patch incorporates Konstantin's comment. Ran some manual tests by running TestBackupNode test with break points in FSEditLog.logSync() and ensured that isSyncRunning is set to false at the end of the method, as intended. All the unit tests passed. Here is the result of test-patch: [exec] -1 overall. [exec] [exec] +1 @author. The patch does not contain any @author tags. [exec] [exec] -1 tests included. The patch doesn't appear to include any new or modified tests. [exec] Please justify why no new tests are needed for this patch. [exec] Also please list what manual steps were performed to verify this patch. [exec] [exec] +1 javadoc. The javadoc tool did not generate any warning messages. [exec] [exec] +1 javac. The applied patch does not increase the total number of javac compiler warnings. [exec] [exec] +1 findbugs. The patch does not introduce any new Findbugs warnings. [exec] [exec] +1 release audit. The applied patch does not increase the total number of release audit warnings. No new tests added as existing tests already cover this functionality.
          Suresh Srinivas made changes -
          Attachment HDFS-119.patch [ 12414931 ]
          Suresh Srinivas made changes -
          Status Patch Available [ 10002 ] Open [ 1 ]
          Hide
          Suresh Srinivas added a comment -

          submitting again...

          Show
          Suresh Srinivas added a comment - submitting again...
          Suresh Srinivas made changes -
          Status Open [ 1 ] Patch Available [ 10002 ]
          Hide
          Konstantin Shvachko added a comment -

          I just committed this. Thank you Suresh.

          Show
          Konstantin Shvachko added a comment - I just committed this. Thank you Suresh.
          Konstantin Shvachko made changes -
          Status Patch Available [ 10002 ] Resolved [ 5 ]
          Hadoop Flags [Reviewed]
          Fix Version/s 0.21.0 [ 12314046 ]
          Resolution Fixed [ 1 ]
          Hide
          Hudson added a comment -

          Integrated in Hadoop-Hdfs-trunk #35 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/35/)
          . Fix a bug in logSync(), which causes NameNode block forever. Contributed by Suresh Srinivas.

          Show
          Hudson added a comment - Integrated in Hadoop-Hdfs-trunk #35 (See http://hudson.zones.apache.org/hudson/job/Hadoop-Hdfs-trunk/35/ ) . Fix a bug in logSync(), which causes NameNode block forever. Contributed by Suresh Srinivas.
          Hide
          Hadoop QA added a comment -

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

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

          -1 tests included. The patch doesn't appear to include any new or modified tests.
          Please justify why no new tests are needed for this patch.
          Also please list what manual steps were performed to verify this patch.

          -1 patch. The patch command could not apply the patch.

          Console output: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-vesta.apache.org/39/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/12414931/HDFS-119.patch against trunk revision 799769. +1 @author. The patch does not contain any @author tags. -1 tests included. The patch doesn't appear to include any new or modified tests. Please justify why no new tests are needed for this patch. Also please list what manual steps were performed to verify this patch. -1 patch. The patch command could not apply the patch. Console output: http://hudson.zones.apache.org/hudson/job/Hdfs-Patch-vesta.apache.org/39/console This message is automatically generated.
          Hide
          Suresh Srinivas added a comment -

          The patch could not be applied because it was already committed before hudson ran the test. The hudson failure can be ignored.

          Show
          Suresh Srinivas added a comment - The patch could not be applied because it was already committed before hudson ran the test. The hudson failure can be ignored.
          Tom White made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Hide
          Konstantin Shvachko added a comment -

          This has never been ported to 0.20. And I have seen NN stuck in wait() on all threads, when one of the drives got full.

          2012-04-05 05:25:52,817 ERROR org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Unable to sync edit log. Fatal Error.
          2012-04-05 05:25:52,818 INFO org.apache.hadoop.hdfs.server.common.Storage:  removing /name/3
          2012-04-05 05:25:53,016 INFO org.apache.hadoop.ipc.Server: IPC Server handler 108 on 8020, call create(/myDir/myFile, rwxr-xr-x, DFSClient_attempt_201204032140_3909_r_000891_0, true, 3, 134217728) from aaa.bbb.ccc.ddd:12345: error: java.io.IOException: java.lang.IndexOutOfBoundsException: Index: 2, Size: 2
          java.io.IOException: java.lang.IndexOutOfBoundsException: Index: 2, Size: 2
                  at java.util.ArrayList.RangeCheck(ArrayList.java:547)
                  at java.util.ArrayList.get(ArrayList.java:322)
                  at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:961)
                  at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startFile(FSNamesystem.java:1123)
                  at org.apache.hadoop.hdfs.server.namenode.NameNode.create(NameNode.java:551)
                  at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
                  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                  at java.lang.reflect.Method.invoke(Method.java:597)
                  at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:524)
                  at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1386)
                  at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1382)
                  at java.security.AccessController.doPrivileged(Native Method)
                  at javax.security.auth.Subject.doAs(Subject.java:396)
                  at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1059)
                  at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1380)
          

          Looks like a critical bug to me.

          Show
          Konstantin Shvachko added a comment - This has never been ported to 0.20. And I have seen NN stuck in wait() on all threads, when one of the drives got full. 2012-04-05 05:25:52,817 ERROR org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Unable to sync edit log. Fatal Error. 2012-04-05 05:25:52,818 INFO org.apache.hadoop.hdfs.server.common.Storage: removing /name/3 2012-04-05 05:25:53,016 INFO org.apache.hadoop.ipc.Server: IPC Server handler 108 on 8020, call create(/myDir/myFile, rwxr-xr-x, DFSClient_attempt_201204032140_3909_r_000891_0, true , 3, 134217728) from aaa.bbb.ccc.ddd:12345: error: java.io.IOException: java.lang.IndexOutOfBoundsException: Index: 2, Size: 2 java.io.IOException: java.lang.IndexOutOfBoundsException: Index: 2, Size: 2 at java.util.ArrayList.RangeCheck(ArrayList.java:547) at java.util.ArrayList.get(ArrayList.java:322) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.logSync(FSEditLog.java:961) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startFile(FSNamesystem.java:1123) at org.apache.hadoop.hdfs.server.namenode.NameNode.create(NameNode.java:551) at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:524) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1386) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:1382) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:396) at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1059) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:1380) Looks like a critical bug to me.
          Hide
          Konstantin Shvachko added a comment -

          Here is the patch for branch-1.0

          Show
          Konstantin Shvachko added a comment - Here is the patch for branch-1.0
          Konstantin Shvachko made changes -
          Attachment HDFS-119-branch-1.0.patch [ 12521803 ]
          Hide
          Konstantin Shvachko added a comment -

          Tested this with a small partition setup on a drive, and with a small flash drive used as the second storage directory. I ran NNThroughputBenchmark –op create so that edits fill up the small partition and NN excludes it from storage directories.

          Show
          Konstantin Shvachko added a comment - Tested this with a small partition setup on a drive, and with a small flash drive used as the second storage directory. I ran NNThroughputBenchmark –op create so that edits fill up the small partition and NN excludes it from storage directories.
          Hide
          Brandon Li added a comment -

          Hi Konst,

          The patch looks good to me. (nit: the indent seems not aligned)

          Thanks,
          Brandon

          P.S. I've got one question that is remotely related with this issue: method removeEditsStreamsAndStorageDirs() could unneceissarily invoke fatalExit() if another thread removes one error editStream before current thread does?

          Show
          Brandon Li added a comment - Hi Konst, The patch looks good to me. (nit: the indent seems not aligned) Thanks, Brandon P.S. I've got one question that is remotely related with this issue: method removeEditsStreamsAndStorageDirs() could unneceissarily invoke fatalExit() if another thread removes one error editStream before current thread does?
          Hide
          Konstantin Shvachko added a comment -

          > (nit: the indent seems not aligned)

          Yes, I thought that way it is easier to see what the actual changes are. Indentation can be corrected as style change just before the commit.

          > removeEditsStreamsAndStorageDirs() could unneceissarily invoke fatalExit()

          Good point. Even though it's a theoretical possibility, because removeEditsStreamsAndStorageDirs() is called only in logSync(), when isSyncRunning == true, so everybody else should be waiting for sync to complete. But people tend to change code and use methods already defined, so let's file a jira.

          Show
          Konstantin Shvachko added a comment - > (nit: the indent seems not aligned) Yes, I thought that way it is easier to see what the actual changes are. Indentation can be corrected as style change just before the commit. > removeEditsStreamsAndStorageDirs() could unneceissarily invoke fatalExit() Good point. Even though it's a theoretical possibility, because removeEditsStreamsAndStorageDirs() is called only in logSync(), when isSyncRunning == true , so everybody else should be waiting for sync to complete. But people tend to change code and use methods already defined, so let's file a jira.
          Hide
          Brandon Li added a comment -

          This race could be between logSync requests, or between logSync and any place where a storage directory may be removed, e.g., during checkpointing. HDFS-3264 has been filed for this issue.

          Show
          Brandon Li added a comment - This race could be between logSync requests, or between logSync and any place where a storage directory may be removed, e.g., during checkpointing. HDFS-3264 has been filed for this issue.
          Hide
          Suresh Srinivas added a comment -

          +1 for the patch.

          Show
          Suresh Srinivas added a comment - +1 for the patch.
          Hide
          Konstantin Shvachko added a comment -

          Updated patch to reflect current branch state. No code changes, just line numbers.
          Plus the code style change (indentation), suggested by Brandon.

          Show
          Konstantin Shvachko added a comment - Updated patch to reflect current branch state. No code changes, just line numbers. Plus the code style change (indentation), suggested by Brandon.
          Konstantin Shvachko made changes -
          Attachment HDFS-119-branch-1.0.patch [ 12522538 ]
          Hide
          Konstantin Shvachko added a comment -

          Committed to branch 1.

          Show
          Konstantin Shvachko added a comment - Committed to branch 1.
          Konstantin Shvachko made changes -
          Fix Version/s 1.1.0 [ 12317959 ]
          Component/s name-node [ 12312926 ]
          Hide
          Brandon Li added a comment -

          backport Konstantin's patch to branch1.0

          Show
          Brandon Li added a comment - backport Konstantin's patch to branch1.0
          Brandon Li made changes -
          Attachment HDFS119.branch1.0.patch [ 12523510 ]
          Hide
          Konstantin Shvachko added a comment -

          +1 patch for branch1.0 looks good, Brandon.

          Show
          Konstantin Shvachko added a comment - +1 patch for branch1.0 looks good, Brandon.
          Hide
          Tsz Wo Nicholas Sze added a comment -

          Hi Brandon, please run test-patch and all the unit tests on your patch.

          Show
          Tsz Wo Nicholas Sze added a comment - Hi Brandon, please run test-patch and all the unit tests on your patch.
          Matt Foley made changes -
          Fix Version/s 1.0.3 [ 12320249 ]
          Fix Version/s 1.1.0 [ 12317959 ]

            People

            • Assignee:
              Suresh Srinivas
              Reporter:
              Konstantin Shvachko
            • Votes:
              0 Vote for this issue
              Watchers:
              10 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development