[ https://issues.apache.org/jira/browse/HDFS-3530?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13395853#comment-13395853 ]
Sho Shimauchi commented on HDFS-3530: ------------------------------------- The following log appears in the Jenkins log: {quote} 2012-06-12 23:58:17,839 INFO namenode.FileJournalManager (FileJournalManager.java:finalizeLogSegment(100)) - Finalizing edits file /home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inprogress_0000000000000000001 -> /home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_0000000000000000001-0000000000000001003 2012-06-12 23:58:17,839 ERROR namenode.NNStorage (NNStorage.java:reportErrorsOnDirectory(888)) - Error reported on storage directory Storage Directory /home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1 2012-06-12 23:58:17,840 WARN namenode.NNStorage (NNStorage.java:reportErrorsOnDirectory(893)) - About to remove corresponding storage: /home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1 2012-06-12 23:58:17,840 ERROR namenode.FSEditLog (JournalSet.java:mapJournalsAndReportErrors(341)) - Error: finalize log segment 1, 1003 failed for (journal JournalAndStream(mgr=FileJournalManager(root=/home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1), stream=null)) java.lang.IllegalStateException: Unable to finalize edits file /home/jenkins/jenkins-slave/workspace/PreCommit-HADOOP-Build/trunk/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inprogress_0000000000000000001 at org.apache.hadoop.hdfs.server.namenode.FileJournalManager.finalizeLogSegment(FileJournalManager.java:107) at org.apache.hadoop.hdfs.server.namenode.JournalSet$3.apply(JournalSet.java:198) at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:323) at org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:193) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:980) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.close(FSEditLog.java:324) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.stopActiveServices(FSNamesystem.java:676) at org.apache.hadoop.hdfs.server.namenode.NameNode$NameNodeHAContext.stopActiveServices(NameNode.java:1325) at org.apache.hadoop.hdfs.server.namenode.ha.ActiveState.exitState(ActiveState.java:70) at org.apache.hadoop.hdfs.server.namenode.NameNode.stop(NameNode.java:630) at org.apache.hadoop.hdfs.MiniDFSCluster.shutdown(MiniDFSCluster.java:1309) at org.apache.hadoop.hdfs.TestFileAppend2.testComplexAppend(TestFileAppend2.java:379) 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 junit.framework.TestCase.runTest(TestCase.java:168) at junit.framework.TestCase.runBare(TestCase.java:134) at junit.framework.TestResult$1.protect(TestResult.java:110) at junit.framework.TestResult.runProtected(TestResult.java:128) at junit.framework.TestResult.run(TestResult.java:113) at junit.framework.TestCase.run(TestCase.java:124) at junit.framework.TestSuite.runTest(TestSuite.java:243) at junit.framework.TestSuite.run(TestSuite.java:238) at org.junit.internal.runners.JUnit38ClassRunner.run(JUnit38ClassRunner.java:83) at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:236) at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:134) at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:113) 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.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:189) at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:165) at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:85) at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:103) at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74) {quote} This exception looks similar to HDFS-2939. FileJournalManager.finalizeLogSegment() failed to rename an inprogress edits file to finalize file. {code} @Override synchronized public void finalizeLogSegment(long firstTxId, long lastTxId) throws IOException { File inprogressFile = NNStorage.getInProgressEditsFile(sd, firstTxId); File dstFile = NNStorage.getFinalizedEditsFile( sd, firstTxId, lastTxId); LOG.info("Finalizing edits file " + inprogressFile + " -> " + dstFile); Preconditions.checkState(!dstFile.exists(), "Can't finalize edits file " + inprogressFile + " since finalized file " + "already exists"); if (!inprogressFile.renameTo(dstFile)) { storage.reportErrorsOnDirectory(sd); throw new IllegalStateException("Unable to finalize edits file " + inprogressFile); } if (inprogressFile.equals(currentInProgress)) { currentInProgress = null; } } {code} One of the probable cause of renaming failure is the inprogress file was not closed. It is closed just before finalizedLogSegment() in JournalSet.JournalClosure.apply(), but the code block is not synchronized. {code} @Override public void finalizeLogSegment(final long firstTxId, final long lastTxId) throws IOException { mapJournalsAndReportErrors(new JournalClosure() { @Override public void apply(JournalAndStream jas) throws IOException { if (jas.isActive()) { jas.closeStream(); jas.getManager().finalizeLogSegment(firstTxId, lastTxId); } } }, "finalize log segment " + firstTxId + ", " + lastTxId); } {code} So I guess some race condition happens in the above part. Is it ok to just enclose jas.closeStream() and jas.getManager().finalizeLogSegment() in synchronized block? > TestFileAppend2.testComplexAppend occasionally fails > ---------------------------------------------------- > > Key: HDFS-3530 > URL: https://issues.apache.org/jira/browse/HDFS-3530 > Project: Hadoop HDFS > Issue Type: Bug > Components: test > Reporter: Eli Collins > Attachments: PreCommit-HADOOP-Build #1116 test - > testComplexAppend.html.gz > > > TestFileAppend2.testComplexAppend occasionally fails with the following: > junit.framework.AssertionFailedError: testComplexAppend Worker encountered > exceptions. > at junit.framework.Assert.fail(Assert.java:47) > at junit.framework.Assert.assertTrue(Assert.java:20) > at > org.apache.hadoop.hdfs.TestFileAppend2.testComplexAppend(TestFileAppend2.java:385) -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa For more information on JIRA, see: http://www.atlassian.com/software/jira