Uploaded image for project: 'Edgent'
  1. Edgent
  2. EDGENT-258

testMultiTopologyPollWithError failure; CME in TrackingScheduledExecutor.cancelAllAsyncTasks()

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Duplicate
    • None
    • None
    • Runtime, Test
    • None

    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]

      Attachments

        Activity

          People

            Unassigned Unassigned
            dlaboss Dale LaBossiere
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: