[ 
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

        

Reply via email to