Dale LaBossiere created EDGENT-258:
--------------------------------------
Summary: 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.
[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)
