[
https://issues.apache.org/jira/browse/EDGENT-258?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dale LaBossiere updated EDGENT-258:
-----------------------------------
Description:
This happened in an (ant) travis-ci run.
The DirectTStreamTest.testMultiTopologyPollWithError() test failed with a
CancellationException (end of the traces below). Perhaps that was fallout from
a CME reported within TrackingScheduledExecutor.cancelAllAsyncTasks() on the
iteration of asyncTasks @ TrackingScheduledExecutor:121 which is the line:
for (RunnableScheduledFuture<?> task : asyncTasks) {
(there's also an InterruptedException below)
But I don't see how that CME can happen. asyncTasks is a (private)
SynchronizedSet and all iteration on it in TrackingScheduledExecutor does the
required "synchronized(asyncTasks) { iterate... }" pattern. The
SynchronizedSet methods all synchronize on the SynchronizedSet object
(asyncTasks) too so
an operation like add() or remove() can't occur during that synchronized
iteration. All access to the underlying set is via the SynchronizedSet. So how
can that CME happen???
The only possible non-CME-inducing flaw I see is in removeTrack() where there's
the non-synchronized sequential access:
asyncTasks.remove();
if (asyncTasks.isEmpty() ... // hence may not reflect state following
preceeding remove()
Note, there should normally only be 4 instances reporting "Expected Test
Exception" but there a 8 (maybe due to removeTrack()?). Trust me, they're all
from this test method execution. I've triple checked :-)
I'm also confused a bit by the thread pool/thread ids reported on those 8
instances. Would have expected them to all be associated with the test's
allocated fixed thread pool and would have expected that to have a single pool
with 4 thread. But that doesn't seem to be the case?
Here's the various msgs from the test's execution. Maybe someone else can
figure it out. From
https://travis-ci.org/apache/incubator-edgent/builds/164076026
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
[junit] at
org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:83)
[junit] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit] at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Caused by: java.lang.RuntimeException: Expected Test Exception
[junit] at
org.apache.edgent.test.topology.TStreamTest.lambda$null$5f279479$1(TStreamTest.java:774)
[junit] at
org.apache.edgent.test.topology.TStreamTest$$Lambda$8/2070622949.accept(Unknown
Source)
[junit] at
org.apache.edgent.function.Functions$ThreadSafeConsumer.accept(Functions.java:204)
[junit] at
org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at org.apache.edgent.oplet.core.FanOut.accept(FanOut.java:50)
[junit] at
org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at org.apache.edgent.oplet.core.Source.submit(Source.java:47)
[junit] at
org.apache.edgent.oplet.functional.SupplierPeriodicSource.fetchTuples(SupplierPeriodicSource.java:52)
[junit] at
org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:81)
[junit] ... 9 more
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.ThreadFactoryTracker
trackedThreadUncaughtException
[junit] SEVERE: Uncaught exception in thread
pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be
[junit] java.util.ConcurrentModificationException
[junit] at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
[junit] at java.util.HashMap$KeyIterator.next(HashMap.java:1453)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cancelAllAsyncTasks(TrackingScheduledExecutor.java:121)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cleanup(TrackingScheduledExecutor.java:115)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.afterExecute(TrackingScheduledExecutor.java:88)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1150)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-15-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
... like the first above
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-11-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM org.apache.edgent.runtime.etiao.Executable
invokeAction
[junit] SEVERE: Exception caught while waiting for future to complete
[junit] java.lang.InterruptedException
[junit] at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit] at
java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
[junit] at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:462)
[junit] at
java.util.concurrent.ExecutorCompletionService.poll(ExecutorCompletionService.java:202)
[junit] at
org.apache.edgent.runtime.etiao.Executable.invokeAction(Executable.java:222)
[junit] at
org.apache.edgent.runtime.etiao.Executable.start(Executable.java:180)
[junit] at
org.apache.edgent.runtime.etiao.EtiaoJob.stateChange(EtiaoJob.java:107)
[junit] at
org.apache.edgent.providers.direct.DirectTopology.execute(DirectTopology.java:110)
[junit] at
org.apache.edgent.providers.direct.DirectTopology.access$000(DirectTopology.java:46)
[junit] at
org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:89)
[junit] at
org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:85)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-9-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-7-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-8-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-8-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-1-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-2-thread-1-b0a11f1a-309f-48d3-a0cc-72ccd245fefd: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
==================================
Reported test failure:
[junit] Testcase:
testMultiTopologyPollWithError(org.apache.edgent.test.providers.direct.topology.DirectTStreamTest):
Caused an ERROR
[junit] java.util.concurrent.CancellationException
[junit] java.util.concurrent.ExecutionException:
java.util.concurrent.CancellationException
[junit] at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[junit] at java.util.concurrent.FutureTask.get(FutureTask.java:192)
[junit] at
org.apache.edgent.test.topology.TStreamTest.waitForCompletion(TStreamTest.java:867)
[junit] at
org.apache.edgent.test.topology.TStreamTest.testMultiTopologyPollWithError(TStreamTest.java:781)
[junit] Caused by: java.util.concurrent.CancellationException
[junit] at java.util.concurrent.FutureTask.report(FutureTask.java:121)
[junit] at java.util.concurrent.FutureTask.get(FutureTask.java:206)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.get(TrackingScheduledExecutor.java:255)
[junit] at
org.apache.edgent.topology.spi.tester.AbstractTester.complete(AbstractTester.java:46)
[junit] at
org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:72)
[junit] at
org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:76)
[junit] at
org.apache.edgent.test.topology.TStreamTest.lambda$testMultiTopologyPollWithError$2(TStreamTest.java:777)
[junit] at
org.apache.edgent.test.topology.TStreamTest$$Lambda$1/1233595751.call(Unknown
Source)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit]
was:
This happened in an (ant) travis-ci run.
The DirectTStreamTest.testMultiTopologyPollWithError() test failed with a
CancellationException (end of the traces below). Perhaps that was fallout from
a CME reported within TrackingScheduledExecutor.cancelAllAsyncTasks() on the
iteration of asyncTasks @ TrackingScheduledExecutor:121 which is the line:
for (RunnableScheduledFuture<?> task : asyncTasks) {
(there's also an InterruptedException below)
But I don't see how that CME can happen. asyncTasks is a (private)
SynchronizedSet and all iteration on it in TrackingScheduledExecutor does the
required "synchronized(asyncTasks) { iterate... }" pattern. The
SynchronizedSet methods all synchronize on the SynchronizedSet object
(asyncTasks) too so
an operation like add() or remove() can't occur during that synchronized
iteration. All access to the underlying set is via the SynchronizedSet. So how
can that CME happen???
The only possible non-CME-inducing flaw I see is in removeTrack() where there's
the non-synchronized sequential access:
asyncTasks.remove();
if (asyncTasks.isEmpty() ... // hence may not reflect state following
preceeding remove()
Note, there should normally only be 4 instances reporting "Expected Test
Exception" but there a 8 (maybe due to removeTrack()?). Trust me, they're all
from this test method execution. I've triple checked :-)
I'm also confused a bit by the thread pool/thread ids reported on those 8
instances. Would have expected them to all be associated with the test's
allocated fixed thread pool and would have expected that to have a single pool
with 4 thread. But that doesn't seem to be the case?
Here's the various msgs from the test's execution. Maybe someone else can
figure it out.
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
[junit] at
org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:83)
[junit] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit] at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Caused by: java.lang.RuntimeException: Expected Test Exception
[junit] at
org.apache.edgent.test.topology.TStreamTest.lambda$null$5f279479$1(TStreamTest.java:774)
[junit] at
org.apache.edgent.test.topology.TStreamTest$$Lambda$8/2070622949.accept(Unknown
Source)
[junit] at
org.apache.edgent.function.Functions$ThreadSafeConsumer.accept(Functions.java:204)
[junit] at
org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at org.apache.edgent.oplet.core.FanOut.accept(FanOut.java:50)
[junit] at
org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
[junit] at org.apache.edgent.oplet.core.Source.submit(Source.java:47)
[junit] at
org.apache.edgent.oplet.functional.SupplierPeriodicSource.fetchTuples(SupplierPeriodicSource.java:52)
[junit] at
org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:81)
[junit] ... 9 more
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.ThreadFactoryTracker
trackedThreadUncaughtException
[junit] SEVERE: Uncaught exception in thread
pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be
[junit] java.util.ConcurrentModificationException
[junit] at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
[junit] at java.util.HashMap$KeyIterator.next(HashMap.java:1453)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cancelAllAsyncTasks(TrackingScheduledExecutor.java:121)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cleanup(TrackingScheduledExecutor.java:115)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.afterExecute(TrackingScheduledExecutor.java:88)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1150)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-15-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
... like the first above
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-11-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM org.apache.edgent.runtime.etiao.Executable
invokeAction
[junit] SEVERE: Exception caught while waiting for future to complete
[junit] java.lang.InterruptedException
[junit] at
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
[junit] at
java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
[junit] at
java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:462)
[junit] at
java.util.concurrent.ExecutorCompletionService.poll(ExecutorCompletionService.java:202)
[junit] at
org.apache.edgent.runtime.etiao.Executable.invokeAction(Executable.java:222)
[junit] at
org.apache.edgent.runtime.etiao.Executable.start(Executable.java:180)
[junit] at
org.apache.edgent.runtime.etiao.EtiaoJob.stateChange(EtiaoJob.java:107)
[junit] at
org.apache.edgent.providers.direct.DirectTopology.execute(DirectTopology.java:110)
[junit] at
org.apache.edgent.providers.direct.DirectTopology.access$000(DirectTopology.java:46)
[junit] at
org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:89)
[junit] at
org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:85)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
[junit] at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at
org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-9-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-7-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-5-thread-8-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-8-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-4-thread-1-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
[junit] Sep 30, 2016 4:37:46 PM
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
[junit] SEVERE: Thread:
pool-2-thread-1-b0a11f1a-309f-48d3-a0cc-72ccd245fefd: task terminated with
exception :
[junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
Test Exception
...
==================================
Reported test failure:
[junit] Testcase:
testMultiTopologyPollWithError(org.apache.edgent.test.providers.direct.topology.DirectTStreamTest):
Caused an ERROR
[junit] java.util.concurrent.CancellationException
[junit] java.util.concurrent.ExecutionException:
java.util.concurrent.CancellationException
[junit] at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[junit] at java.util.concurrent.FutureTask.get(FutureTask.java:192)
[junit] at
org.apache.edgent.test.topology.TStreamTest.waitForCompletion(TStreamTest.java:867)
[junit] at
org.apache.edgent.test.topology.TStreamTest.testMultiTopologyPollWithError(TStreamTest.java:781)
[junit] Caused by: java.util.concurrent.CancellationException
[junit] at java.util.concurrent.FutureTask.report(FutureTask.java:121)
[junit] at java.util.concurrent.FutureTask.get(FutureTask.java:206)
[junit] at
org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.get(TrackingScheduledExecutor.java:255)
[junit] at
org.apache.edgent.topology.spi.tester.AbstractTester.complete(AbstractTester.java:46)
[junit] at
org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:72)
[junit] at
org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:76)
[junit] at
org.apache.edgent.test.topology.TStreamTest.lambda$testMultiTopologyPollWithError$2(TStreamTest.java:777)
[junit] at
org.apache.edgent.test.topology.TStreamTest$$Lambda$1/1233595751.call(Unknown
Source)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:745)
[junit]
> testMultiTopologyPollWithError failure; CME in
> TrackingScheduledExecutor.cancelAllAsyncTasks()
> ----------------------------------------------------------------------------------------------
>
> Key: EDGENT-258
> URL: https://issues.apache.org/jira/browse/EDGENT-258
> Project: Edgent
> Issue Type: Bug
> Components: Runtime, Test
> Reporter: Dale LaBossiere
>
> This happened in an (ant) travis-ci run.
> The DirectTStreamTest.testMultiTopologyPollWithError() test failed with a
> CancellationException (end of the traces below). Perhaps that was fallout
> from a CME reported within TrackingScheduledExecutor.cancelAllAsyncTasks() on
> the iteration of asyncTasks @ TrackingScheduledExecutor:121 which is the line:
> for (RunnableScheduledFuture<?> task : asyncTasks) {
> (there's also an InterruptedException below)
> But I don't see how that CME can happen. asyncTasks is a (private)
> SynchronizedSet and all iteration on it in TrackingScheduledExecutor does the
> required "synchronized(asyncTasks) { iterate... }" pattern. The
> SynchronizedSet methods all synchronize on the SynchronizedSet object
> (asyncTasks) too so
> an operation like add() or remove() can't occur during that synchronized
> iteration. All access to the underlying set is via the SynchronizedSet. So
> how can that CME happen???
> The only possible non-CME-inducing flaw I see is in removeTrack() where
> there's the non-synchronized sequential access:
> asyncTasks.remove();
> if (asyncTasks.isEmpty() ... // hence may not reflect state following
> preceeding remove()
> Note, there should normally only be 4 instances reporting "Expected Test
> Exception" but there a 8 (maybe due to removeTrack()?). Trust me, they're
> all from this test method execution. I've triple checked :-)
> I'm also confused a bit by the thread pool/thread ids reported on those 8
> instances. Would have expected them to all be associated with the test's
> allocated fixed thread pool and would have expected that to have a single
> pool with 4 thread. But that doesn't seem to be the case?
> Here's the various msgs from the test's execution. Maybe someone else can
> figure it out. From
> https://travis-ci.org/apache/incubator-edgent/builds/164076026
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> [junit] at
> org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:83)
> [junit] at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> [junit] at
> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> [junit] at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
> [junit] at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [junit] at
> org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
> [junit] at java.lang.Thread.run(Thread.java:745)
> [junit] Caused by: java.lang.RuntimeException: Expected Test Exception
> [junit] at
> org.apache.edgent.test.topology.TStreamTest.lambda$null$5f279479$1(TStreamTest.java:774)
> [junit] at
> org.apache.edgent.test.topology.TStreamTest$$Lambda$8/2070622949.accept(Unknown
> Source)
> [junit] at
> org.apache.edgent.function.Functions$ThreadSafeConsumer.accept(Functions.java:204)
> [junit] at
> org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
> [junit] at org.apache.edgent.oplet.core.FanOut.accept(FanOut.java:50)
> [junit] at
> org.apache.edgent.runtime.etiao.SettableForwarder.accept(SettableForwarder.java:54)
> [junit] at org.apache.edgent.oplet.core.Source.submit(Source.java:47)
> [junit] at
> org.apache.edgent.oplet.functional.SupplierPeriodicSource.fetchTuples(SupplierPeriodicSource.java:52)
> [junit] at
> org.apache.edgent.oplet.core.PeriodicSource.run(PeriodicSource.java:81)
> [junit] ... 9 more
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.ThreadFactoryTracker
> trackedThreadUncaughtException
> [junit] SEVERE: Uncaught exception in thread
> pool-5-thread-7-0a765e86-37c1-4299-9655-118420e3f1be
> [junit] java.util.ConcurrentModificationException
> [junit] at java.util.HashMap$HashIterator.nextNode(HashMap.java:1429)
> [junit] at java.util.HashMap$KeyIterator.next(HashMap.java:1453)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cancelAllAsyncTasks(TrackingScheduledExecutor.java:121)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.cleanup(TrackingScheduledExecutor.java:115)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor.afterExecute(TrackingScheduledExecutor.java:88)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1150)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [junit] at
> org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
> [junit] at java.lang.Thread.run(Thread.java:745)
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-4-thread-15-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ... like the first above
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-5-thread-11-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.Executable invokeAction
> [junit] SEVERE: Exception caught while waiting for future to complete
> [junit] java.lang.InterruptedException
> [junit] at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
> [junit] at
> java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
> [junit] at
> java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:462)
> [junit] at
> java.util.concurrent.ExecutorCompletionService.poll(ExecutorCompletionService.java:202)
> [junit] at
> org.apache.edgent.runtime.etiao.Executable.invokeAction(Executable.java:222)
> [junit] at
> org.apache.edgent.runtime.etiao.Executable.start(Executable.java:180)
> [junit] at
> org.apache.edgent.runtime.etiao.EtiaoJob.stateChange(EtiaoJob.java:107)
> [junit] at
> org.apache.edgent.providers.direct.DirectTopology.execute(DirectTopology.java:110)
> [junit] at
> org.apache.edgent.providers.direct.DirectTopology.access$000(DirectTopology.java:46)
> [junit] at
> org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:89)
> [junit] at
> org.apache.edgent.providers.direct.DirectTopology$1.call(DirectTopology.java:85)
> [junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> [junit] at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
> [junit] at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.run(TrackingScheduledExecutor.java:205)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [junit] at
> org.apache.edgent.runtime.etiao.ThreadFactoryTracker$2.run(ThreadFactoryTracker.java:87)
> [junit] at java.lang.Thread.run(Thread.java:745)
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-5-thread-9-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-4-thread-7-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-5-thread-8-0a765e86-37c1-4299-9655-118420e3f1be: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-4-thread-8-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-4-thread-1-79a62c35-c201-4800-b5fe-0981a922a901: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> [junit] Sep 30, 2016 4:37:46 PM
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor afterExecute
> [junit] SEVERE: Thread:
> pool-2-thread-1-b0a11f1a-309f-48d3-a0cc-72ccd245fefd: task terminated with
> exception :
> [junit] java.lang.RuntimeException: java.lang.RuntimeException: Expected
> Test Exception
> ...
> ==================================
> Reported test failure:
> [junit] Testcase:
> testMultiTopologyPollWithError(org.apache.edgent.test.providers.direct.topology.DirectTStreamTest):
> Caused an ERROR
> [junit] java.util.concurrent.CancellationException
> [junit] java.util.concurrent.ExecutionException:
> java.util.concurrent.CancellationException
> [junit] at java.util.concurrent.FutureTask.report(FutureTask.java:122)
> [junit] at java.util.concurrent.FutureTask.get(FutureTask.java:192)
> [junit] at
> org.apache.edgent.test.topology.TStreamTest.waitForCompletion(TStreamTest.java:867)
> [junit] at
> org.apache.edgent.test.topology.TStreamTest.testMultiTopologyPollWithError(TStreamTest.java:781)
> [junit] Caused by: java.util.concurrent.CancellationException
> [junit] at java.util.concurrent.FutureTask.report(FutureTask.java:121)
> [junit] at java.util.concurrent.FutureTask.get(FutureTask.java:206)
> [junit] at
> org.apache.edgent.runtime.etiao.TrackingScheduledExecutor$TrackedFuture.get(TrackingScheduledExecutor.java:255)
> [junit] at
> org.apache.edgent.topology.spi.tester.AbstractTester.complete(AbstractTester.java:46)
> [junit] at
> org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:72)
> [junit] at
> org.apache.edgent.test.topology.TopologyAbstractTest.complete(TopologyAbstractTest.java:76)
> [junit] at
> org.apache.edgent.test.topology.TStreamTest.lambda$testMultiTopologyPollWithError$2(TStreamTest.java:777)
> [junit] at
> org.apache.edgent.test.topology.TStreamTest$$Lambda$1/1233595751.call(Unknown
> Source)
> [junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> [junit] at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> [junit] at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> [junit] at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> [junit] at java.lang.Thread.run(Thread.java:745)
> [junit]
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
