[jira] [Created] (BROOKLYN-227) Exceptions not being logged

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

Aled Sage created BROOKLYN-227:
----------------------------------

             Summary: Exceptions not being logged
                 Key: BROOKLYN-227
                 URL: https://issues.apache.org/jira/browse/BROOKLYN-227
             Project: Brooklyn
          Issue Type: Bug
            Reporter: Aled Sage


In 0.9.0-SNAPSHOT, a couple of times now I've hit exceptions that are not logged anywhere within brooklyn debug log. A good example is:

{noformat}
2016-02-20 22:09:00,037 DEBUG b.l.docker.DockerResolver [brooklyn-execmanager-dO9Ptbsx-0]: Resolving location 'docker:j1M7T5XG:(name="my-docker-cloud-vagrant")' with flags provisioner=FixedListMachineProvisioningLocation{id=DtPfBrpb, name=FixedListMachineProvisioningLocation:DtPf},strat
egies=[DockerAwarePlacementStrategy(MaxContainersPlacementStrategy@j8yVexHt), DockerAwarePlacementStrategy(BreadthFirstPlacementStrategy@ce2SXY0W)],spec.named.name=my-docker-cloud-vagrant,spec.original=my-docker-cloud-vagrant
2016-02-20 22:09:00,048 WARN  o.a.b.c.m.r.RebindExceptionHandlerImpl [brooklyn-execmanager-dO9Ptbsx-0]: Rebind: continuing after problem rebinding entity j1M7T5XG (DockerInfrastructureImpl{id=j1M7T5XG})
java.lang.IllegalStateException: Cannot instantiate location 'LocationDefinition{id='gzuSFMac', name='my-docker-cloud-vagrant', spec='docker:j1M7T5XG:(name="my-docker-cloud-vagrant")', config={provisioner=FixedListMachineProvisioningLocation{id=DtPfBrpb, name=FixedListMachineProvisioningLocation:DtPf}, strategies=[DockerAwarePlacementStrategy(MaxContainersPlacementStrategy@j8yVexHt), DockerAwarePlacementStrategy(BreadthFirstPlacementStrategy@ce2SXY0W)]}}' pointing at docker:j1M7T5XG:(name="my-docker-cloud-vagrant"): java.lang.NullPointerException
        at org.apache.brooklyn.core.location.BasicLocationRegistry.resolve(BasicLocationRegistry.java:490) ~[brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.location.BasicLocationRegistry.resolve(BasicLocationRegistry.java:459) ~[brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at brooklyn.entity.container.DockerUtils$ReloadDockerLocation.reloaded(DockerUtils.java:392) ~[brooklyn-clocker-docker-1.1.0-20160125.1743-p1.jar:1.1.0-20160125.1743-p1]
        at brooklyn.entity.container.docker.DockerInfrastructureImpl.rebind(DockerInfrastructureImpl.java:346) ~[brooklyn-clocker-docker-1.1.0-20160125.1743-p1.jar:1.1.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.AbstractBrooklynObjectRebindSupport.reconstruct(AbstractBrooklynObjectRebindSupport.java:69) ~[brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindIteration.reconstructEverything(RebindIteration.java:623) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindIteration.doRun(RebindIteration.java:242) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.InitialFullRebindIteration.doRun(InitialFullRebindIteration.java:69) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindIteration.run(RebindIteration.java:265) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindManagerImpl.rebindImpl(RebindManagerImpl.java:552) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindManagerImpl$3.call(RebindManagerImpl.java:502) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.core.mgmt.rebind.RebindManagerImpl$3.call(RebindManagerImpl.java:500) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at org.apache.brooklyn.util.core.task.BasicExecutionManager$SubmissionCallable.call(BasicExecutionManager.java:499) [brooklyn-core-0.9.0-20160125.1743-p1.jar:0.9.0-20160125.1743-p1]
        at java.util.concurrent.FutureTask.run(FutureTask.java:262) [na:1.7.0_71]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_71]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_71]
        at java.lang.Thread.run(Thread.java:745) [na:1.7.0_71]
{noformat}

See the code change that was made in https://github.com/apache/brooklyn-server/commit/4cb25a42938dcc4383bd831d00841d91b400ac99 (where I've just added a comment).

In that particular situation, we should change it to include the cause in the {{IllegalStateException}} that is thrown. Or alternatively we could log the exception, and then throw the new simplified exception (but I'm not convinced of the point in that).

We need to be extremely cautious about using {{Exceptions.collapseText}}. There was another situation recently that I need to dig out when I have a few minutes, where another NullPointerException wasn't being logged anywhere, except for that one phrase (I think it was when calling an effector from the REST api).



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