[
https://issues.apache.org/jira/browse/HADOOP-15003?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16259372#comment-16259372
]
Steve Loughran commented on HADOOP-15003:
-----------------------------------------
Test failure looks legit & presumably concurrency; managed to replicate by
significantly increasing the #of threads and tasks
{code}
2017-11-20 15:30:41,309 [testFailFastCallRevertSuppressed[3]-pool-0] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=1, limit=8, item=Item{id=1, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=1, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=1,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,309 [testFailFastCallRevertSuppressed[3]-pool-1] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=2, limit=8, item=Item{id=2, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=2, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=2,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,309 [testFailFastCallRevertSuppressed[3]-pool-2] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=3, limit=8, item=Item{id=3, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=3, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=3,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,309 [testFailFastCallRevertSuppressed[3]-pool-3] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=4, limit=8, item=Item{id=4, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=4, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=4,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,309 [testFailFastCallRevertSuppressed[3]-pool-4] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=5, limit=8, item=Item{id=5, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=5, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=5,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-5] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=6, limit=8, item=Item{id=6, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=6, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=6,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-6] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=7, limit=8, item=Item{id=7, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=7, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=7,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-0] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=8, limit=8, item=Item{id=9, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=9, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=9,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-5] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=15, limit=8, item=Item{id=15, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=15, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=15,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-4] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=14, limit=8, item=Item{id=14, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=14, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=14,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-3] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=13, limit=8, item=Item{id=13, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=13, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=13,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-6] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=12, limit=8, item=Item{id=12, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=12, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=12,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-2] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=11, limit=8, item=Item{id=12, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=11, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=11,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-7] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=10, limit=8, item=Item{id=11, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=8, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=8,
committed=true, aborted=false, reverted=false, text=With 8 threads}
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-1] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failing
committer', count=9, limit=8, item=Item{id=10, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=10, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=10,
committed=true, aborted=false, reverted=false, text=With 8 threads}
/** this is the failing task */
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-5] INFO
commit.Tasks (Tasks.java:run(287)) - Aborting task
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-0] INFO
commit.Tasks (Tasks.java:run(263)) - Task failed
java.io.IOException: BaseCounter{name='failing committer', count=15, limit=8,
item=Item{id=15, committed=true, aborted=false, reverted=false, text=With 8
threads}}: Limit 8 reached for Item{id=9, committed=true, aborted=false,
reverted=false, text=With 8 threads}
at
org.apache.hadoop.fs.s3a.commit.TestTasks$BaseCounter.process(TestTasks.java:460)
at
org.apache.hadoop.fs.s3a.commit.TestTasks$CounterTask.run(TestTasks.java:509)
at
org.apache.hadoop.fs.s3a.commit.TestTasks$CounterTask.run(TestTasks.java:499)
at org.apache.hadoop.fs.s3a.commit.Tasks$Builder$1.run(Tasks.java:254)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
2017-11-20 15:30:41,310 [testFailFastCallRevertSuppressed[3]-pool-5] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='aborter',
count=1, limit=0, item=Item{id=16, committed=false, aborted=true,
reverted=false, text=With 8 threads}}: Item{id=16, committed=false,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=16,
committed=false, aborted=true, reverted=false, text=With 8 threads}
/* this is task ID #9 still being executed */
2017-11-20 15:30:41,311 [testFailFastCallRevertSuppressed[3]-pool-0] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='failures',
count=1, limit=0, item=Item{id=9, committed=true, aborted=false,
reverted=false, text=With 8 threads}}: Item{id=9, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=9,
committed=true, aborted=false, reverted=false, text=With 8 threads}
/* reverter starts, but only has 14 successful tasks: it hasn't picked up #9
yet */
2017-11-20 15:30:41,321 [JUnit-testFailFastCallRevertSuppressed[3]] INFO
commit.Tasks (Tasks.java:runParallel(309)) - Reverting all 14 succeeded tasks
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-4] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=1, limit=0, item=Item{id=1, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=1, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=1, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-2] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=4, limit=0, item=Item{id=4, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=4, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=4, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-6] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=3, limit=0, item=Item{id=3, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=3, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=3, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-3] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=2, limit=0, item=Item{id=2, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=2, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=2, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-6] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=11, limit=0, item=Item{id=12, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=12, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=12,
committed=true, aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-2] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=10, limit=0, item=Item{id=13, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=13, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=13,
committed=true, aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-0] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=9, limit=0, item=Item{id=14, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=14, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=14,
committed=true, aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-5] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=8, limit=0, item=Item{id=7, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=7, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=7, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-7] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=6, limit=0, item=Item{id=6, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=5, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=5, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-4] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=7, limit=0, item=Item{id=7, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=15, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=15, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-1] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=6, limit=0, item=Item{id=6, committed=true, aborted=false, reverted=true,
text=With 8 threads}}: Item{id=6, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=6, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-2] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=14, limit=0, item=Item{id=10, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=10, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=10,
committed=true, aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-6] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=13, limit=0, item=Item{id=8, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=8, committed=true, aborted=false,
reverted=false, text=With 8 threads} -> Item{id=8, committed=true,
aborted=false, reverted=true, text=With 8 threads}
2017-11-20 15:30:41,322 [testFailFastCallRevertSuppressed[3]-pool-3] INFO
commit.TestTasks (TestTasks.java:process(458)) - BaseCounter{name='reverter',
count=12, limit=0, item=Item{id=11, committed=true, aborted=false,
reverted=true, text=With 8 threads}}: Item{id=11, committed=true,
aborted=false, reverted=false, text=With 8 threads} -> Item{id=11,
committed=true, aborted=false, reverted=true, text=With 8 threads}
/* so the assertion: "all committed tasks were reverted " doesn't hold. */
java.lang.AssertionError: Item{id=9, committed=true, aborted=false,
reverted=false, text=With 8 threads} was not reverted in [Item{id=1,
committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=2, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=3, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=4, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=5, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=6, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=7, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=8, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=9, committed=true, aborted=false, reverted=false, text=With 8 threads}
Item{id=10, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=11, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=12, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=13, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=14, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=15, committed=true, aborted=false, reverted=true, text=With 8 threads}
Item{id=16, committed=false, aborted=true, reverted=false, text=With 8 threads}]
at org.junit.Assert.fail(Assert.java:88)
at org.junit.Assert.assertTrue(Assert.java:41)
at
org.apache.hadoop.fs.s3a.commit.TestTasks$Item.assertReverted(TestTasks.java:402)
at
java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184)
at
java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at
java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
at
java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
at
java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151)
at
java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
at
java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418)
at
org.apache.hadoop.fs.s3a.commit.TestTasks.testFailFastCallRevertSuppressed(TestTasks.java:231)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
at
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:74)
{code}
> Merge S3A committers into trunk: Yetus patch checker
> ----------------------------------------------------
>
> Key: HADOOP-15003
> URL: https://issues.apache.org/jira/browse/HADOOP-15003
> Project: Hadoop Common
> Issue Type: Sub-task
> Components: fs/s3
> Affects Versions: 3.0.0
> Reporter: Steve Loughran
> Assignee: Steve Loughran
> Attachments: HADOOP-13786-041.patch, HADOOP-13786-042.patch,
> HADOOP-13786-043.patch, HADOOP-13786-044.patch, HADOOP-13786-045.patch,
> HADOOP-13786-046.patch, HADOOP-13786-047.patch, HADOOP-13786-048.patch,
> HADOOP-13786-049.patch, HADOOP-13786-050.patch, HADOOP-13786-051.patch,
> HADOOP-15033-testfix-1.diff
>
>
> This is a Yetus only JIRA created to have Yetus review the
> HADOOP-13786/HADOOP-14971 patch as a .patch file, as the review PR
> [https://github.com/apache/hadoop/pull/282] is stopping this happening in
> HADOOP-14971.
> Reviews should go into the PR/other task
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
---------------------------------------------------------------------
To unsubscribe, e-mail: common-issues-unsubscr...@hadoop.apache.org
For additional commands, e-mail: common-issues-h...@hadoop.apache.org
