[jira] [Created] (BROOKLYN-242) TimeoutException calling Entities.invokeEffectorList (after far too short a time)

["Aled Sage (JIRA)" <ji...@apache.org>]

Aled Sage created BROOKLYN-242:
----------------------------------

             Summary: TimeoutException calling Entities.invokeEffectorList (after far too short a time)
                 Key: BROOKLYN-242
                 URL: https://issues.apache.org/jira/browse/BROOKLYN-242
             Project: Brooklyn
          Issue Type: Bug
            Reporter: Aled Sage


Encountered with Brooklyn 0.9.0-SNAPSHOT, while working on https://github.com/apache/brooklyn-server/pull/59.

While running {{ClockerDynamicLocationPatternRebindTest.testRebind()}} (in brooklyn-server's software/base), I saw this warning and TimeoutException in the log. The test passed successfully.

This exception is particularly surprising because the {{StubInfrastructureImpl.stop}} uses {{Entities.invokeEffectorList(this, applications, Startable.STOP).get(Duration.THIRTY_SECONDS)}}, and the test only took a total of 10 seconds!

It seems that somehow our {{invokeEffectorList}} task threw a {{java.util.concurrent.TimeoutException}} just 10ms after it invoked the stop?! Interestingly, the list of entities on which we were invoking stop is empty.

I've added some unit tests in {{EffectorBasicTest}}, but can't reproduce.

Looking more at the code in {{BasicTask.get()}}, the problem is that we've checked {{isDone()}} and then immediately called {{internalFuture.get(1, TimeUnit.MILLISECONDS)}}. Somehow the {{isDone()}} doesn't agree with the internalFuture's view of whether the task is complete.

{noformat}
2016-03-22 11:49:35,741 WARN  o.a.b.c.l.d.c.StubInfrastructureImpl [brooklyn-execmanager-MYxwdqBj-24]: Error stopping applications
java.util.concurrent.TimeoutException: null
        at java.util.concurrent.FutureTask.get(FutureTask.java:201) [na:1.7.0_65]
        at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:69) ~[guava-17.0.jar:na]
        at org.apache.brooklyn.util.core.task.BasicTask.get(BasicTask.java:454) ~[classes/:na]
        at org.apache.brooklyn.core.location.dynamic.clocker.StubInfrastructureImpl.stop(StubInfrastructureImpl.java:149) ~[test-classes/:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_65]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_65]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_65]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_65]
        at org.codehaus.groovy.reflection.CachedMethod.invoke(CachedMethod.java:90) [groovy-all-2.3.7.jar:2.3.7]
        at groovy.lang.MetaMethod.doMethodInvoke(MetaMethod.java:324) [groovy-all-2.3.7.jar:2.3.7]
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1207) [groovy-all-2.3.7.jar:2.3.7]
        at groovy.lang.MetaClassImpl.invokeMethod(MetaClassImpl.java:1016) [groovy-all-2.3.7.jar:2.3.7]
        at groovy.lang.DelegatingMetaClass.invokeMethod(DelegatingMetaClass.java:149) [groovy-all-2.3.7.jar:2.3.7]
        at groovy.lang.MetaObjectProtocol$invokeMethod.call(Unknown Source) [groovy-all-2.3.7.jar:2.3.7]
        at org.apache.brooklyn.util.groovy.GroovyJavaMethods.invokeMethodOnMetaClass(GroovyJavaMethods.java:191) [classes/:na]
        at org.apache.brooklyn.core.mgmt.internal.AbstractManagementContext.invokeEffectorMethodLocal(AbstractManagementContext.java:309) [classes/:na]
        at org.apache.brooklyn.core.mgmt.internal.AbstractManagementContext.invokeEffectorMethodSync(AbstractManagementContext.java:333) [classes/:na]
        at org.apache.brooklyn.core.mgmt.internal.EffectorUtils.invokeMethodEffector(EffectorUtils.java:255) [classes/:na]
        at org.apache.brooklyn.core.effector.MethodEffector.call(MethodEffector.java:149) [classes/:na]
        at org.apache.brooklyn.core.entity.trait.Startable$StopEffectorBody.call(Startable.java:68) [classes/:na]
        at org.apache.brooklyn.core.entity.trait.Startable$StopEffectorBody.call(Startable.java:1) [classes/:na]
        at org.apache.brooklyn.core.effector.EffectorTasks$EffectorBodyTaskFactory$1.call(EffectorTasks.java:82) [classes/:na]
        at org.apache.brooklyn.util.core.task.DynamicSequentialTask$DstJob.call(DynamicSequentialTask.java:359) [classes/:na]
        at org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:518) [classes/:na]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_65]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_65]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_65]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_65]
{noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)