edgent-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Dale LaBossiere (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (EDGENT-258) testMultiTopologyPollWithError failure; CME in TrackingScheduledExecutor.cancelAllAsyncTasks()
Date Fri, 30 Sep 2016 19:29:21 GMT

     [ 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)

Mime
View raw message