Exception Reporting: The Why

When things go wrong in a complicated system, I have one question: why?

First off: if you are building in Java you are building a complicated system. The reason people cling to Java nowadays is because of the 10+ years of libraries that have evolved. All those libraries are strung together using raw code, or Spring, or Guice, or Tapestry 5 IoC. In an add-hoc, just-in-time, per-thread, abstractions-R-us world, knowing Why a particular operation was invoked is often more use than knowing what in particular failed.

Today's example: I'm working on better integrating Tapestry and Spring as a first step towards Spring Web Flow integration.

I'm mid way through and things started breaking. Now, a normal system can output an exception:

[ERROR] ContextLoader Context initialization failed
org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'upcase' defined in ServletContext resource [/WEB-INF/applicationContext.xml]: Unsatisfied dependency expressed through constructor argument with index 0 of type [org.example.testapp.services.StringTransformer]: : No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean; nested exception is org.springframework.beans.factory.NoSuchBeanDefinitionException: No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean
 at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:591)
 at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:193)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:925)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:835)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:440)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory$1.run(AbstractAutowireCapableBeanFactory.java:409)
 at java.security.AccessController.doPrivileged(Native Method)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:380)
 at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:264)
 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
 at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:261)
 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:185)
 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:164)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:429)
 at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728)
 at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:380)
 at org.springframework.web.context.ContextLoader.createWebApplicationContext(ContextLoader.java:255)
 at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:199)
 at org.apache.tapestry5.internal.spring.SpringModuleDef$1$1$1.invoke(SpringModuleDef.java:60)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.internal.spring.SpringModuleDef$1$1.createObject(SpringModuleDef.java:56)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator$1.invoke(OperationTrackingObjectCreator.java:45)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator.createObject(OperationTrackingObjectCreator.java:49)
 at org.apache.tapestry5.ioc.internal.SingletonServiceLifecycle.createService(SingletonServiceLifecycle.java:29)
 at org.apache.tapestry5.ioc.internal.LifecycleWrappedServiceCreator.createObject(LifecycleWrappedServiceCreator.java:52)
 at org.apache.tapestry5.ioc.internal.InterceptorStackBuilder.createObject(InterceptorStackBuilder.java:56)
 at org.apache.tapestry5.ioc.internal.RecursiveServiceCreationCheckWrapper.createObject(RecursiveServiceCreationCheckWrapper.java:60)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator$1.invoke(OperationTrackingObjectCreator.java:45)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator.createObject(OperationTrackingObjectCreator.java:49)
 at org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:65)
 at $ConfigurableWebApplicationContext_11e7601a600.delegate($ConfigurableWebApplicationContext_11e7601a600.java)
 at $ConfigurableWebApplicationContext_11e7601a600.getBeansOfType($ConfigurableWebApplicationContext_11e7601a600.java)
 at org.apache.tapestry5.internal.spring.SpringModuleDef$2.provide(SpringModuleDef.java:121)
 at org.apache.tapestry5.internal.spring.SpringModuleDef$3$1$1.invoke(SpringModuleDef.java:170)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.internal.spring.SpringModuleDef$3$1.provide(SpringModuleDef.java:164)
 at org.apache.tapestry5.ioc.internal.services.MasterObjectProviderImpl.provide(MasterObjectProviderImpl.java:38)
 at $MasterObjectProvider_11e7601a5f7.provide($MasterObjectProvider_11e7601a5f7.java)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.getObject(RegistryImpl.java:626)
 at org.apache.tapestry5.ioc.internal.ObjectLocatorImpl.getObject(ObjectLocatorImpl.java:49)
 at org.apache.tapestry5.ioc.internal.util.InternalUtils.calculateInjection(InternalUtils.java:208)
 at org.apache.tapestry5.ioc.internal.util.InternalUtils.access$000(InternalUtils.java:42)
 at org.apache.tapestry5.ioc.internal.util.InternalUtils$2.invoke(InternalUtils.java:255)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.util.InternalUtils.calculateParameters(InternalUtils.java:259)
 at org.apache.tapestry5.ioc.internal.ModuleImpl.constructModuleBuilder(ModuleImpl.java:380)
 at org.apache.tapestry5.ioc.internal.ModuleImpl.access$1000(ModuleImpl.java:36)
 at org.apache.tapestry5.ioc.internal.ModuleImpl$5$1.invoke(ModuleImpl.java:313)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.ModuleImpl$5.run(ModuleImpl.java:308)
 at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier$2.invoke(ConcurrentBarrier.java:198)
 at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier$2.invoke(ConcurrentBarrier.java:196)
 at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:138)
 at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withWrite(ConcurrentBarrier.java:204)
 at org.apache.tapestry5.ioc.internal.ModuleImpl$6.invoke(ModuleImpl.java:323)
 at org.apache.tapestry5.ioc.internal.util.ConcurrentBarrier.withRead(ConcurrentBarrier.java:83)
 at org.apache.tapestry5.ioc.internal.ModuleImpl.getModuleBuilder(ModuleImpl.java:331)
 at org.apache.tapestry5.ioc.internal.ServiceResourcesImpl.getModuleBuilder(ServiceResourcesImpl.java:137)
 at org.apache.tapestry5.ioc.internal.ServiceBuilderMethodInvoker.createObject(ServiceBuilderMethodInvoker.java:47)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator$1.invoke(OperationTrackingObjectCreator.java:45)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator.createObject(OperationTrackingObjectCreator.java:49)
 at org.apache.tapestry5.ioc.internal.SingletonServiceLifecycle.createService(SingletonServiceLifecycle.java:29)
 at org.apache.tapestry5.ioc.internal.LifecycleWrappedServiceCreator.createObject(LifecycleWrappedServiceCreator.java:52)
 at org.apache.tapestry5.ioc.internal.InterceptorStackBuilder.createObject(InterceptorStackBuilder.java:56)
 at org.apache.tapestry5.ioc.internal.RecursiveServiceCreationCheckWrapper.createObject(RecursiveServiceCreationCheckWrapper.java:60)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator$1.invoke(OperationTrackingObjectCreator.java:45)
 at org.apache.tapestry5.ioc.internal.InvokableToRunnable.run(InvokableToRunnable.java:36)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:48)
 at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:89)
 at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:68)
 at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:869)
 at org.apache.tapestry5.ioc.internal.OperationTrackingObjectCreator.createObject(OperationTrackingObjectCreator.java:49)
 at org.apache.tapestry5.ioc.internal.services.JustInTimeObjectCreator.createObject(JustInTimeObjectCreator.java:65)
 at $ServletApplicationInitializer_11e7601a5f6.delegate($ServletApplicationInitializer_11e7601a5f6.java)
 at $ServletApplicationInitializer_11e7601a5f6.initializeApplication($ServletApplicationInitializer_11e7601a5f6.java)
 at org.apache.tapestry5.TapestryFilter.init(TapestryFilter.java:91)
 at org.mortbay.jetty.servlet.FilterHolder.start(FilterHolder.java:71)
 at org.mortbay.jetty.servlet.WebApplicationHandler.initializeServlets(WebApplicationHandler.java:310)
 at org.mortbay.jetty.servlet.WebApplicationContext.doStart(WebApplicationContext.java:509)
 at org.mortbay.util.Container.start(Container.java:72)
 at org.mortbay.http.HttpServer.doStart(HttpServer.java:708)
 at org.mortbay.util.Container.start(Container.java:72)
 at org.apache.tapestry5.test.JettyRunner.createAndStart(JettyRunner.java:140)
 at org.apache.tapestry5.test.JettyRunner.(JettyRunner.java:65)
 at org.apache.tapestry5.test.AbstractIntegrationTestSuite.setup(AbstractIntegrationTestSuite.java:261)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:585)
 at org.testng.internal.MethodHelper.invokeMethod(MethodHelper.java:580)
 at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:416)
 at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:154)
 at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:88)
 at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:167)
 at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:104)
 at org.testng.TestRunner.runWorkers(TestRunner.java:720)
 at org.testng.TestRunner.privateRun(TestRunner.java:590)
 at org.testng.TestRunner.run(TestRunner.java:484)
 at org.testng.SuiteRunner.runTest(SuiteRunner.java:332)
 at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:327)
 at org.testng.SuiteRunner.privateRun(SuiteRunner.java:299)
 at org.testng.SuiteRunner.run(SuiteRunner.java:204)
 at org.testng.TestNG.createAndRunSuiteRunners(TestNG.java:864)
 at org.testng.TestNG.runSuitesLocally(TestNG.java:830)
 at org.testng.TestNG.run(TestNG.java:748)
 at org.testng.remote.RemoteTestNG.run(RemoteTestNG.java:73)
 at org.testng.remote.RemoteTestNG.main(RemoteTestNG.java:124)
Caused by: org.springframework.beans.factory.NoSuchBeanDefinitionException: No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.resolveDependency(DefaultListableBeanFactory.java:613)
 at org.springframework.beans.factory.support.ConstructorResolver.resolveAutowiredArgument(ConstructorResolver.java:622)
 at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:584)
 ... 137 more

... but that's not exactly helpful. Why was it trying to build the Spring ApplicationContext at that time?

That's where Tapestry 5.1 comes in; it carefully tracks what is going on in the IoC container, using a kind of nested diagnostic context:

[ERROR] Registry Error creating bean with name 'upcase' defined in ServletContext resource [/WEB-INF/applicationContext.xml]: Unsatisfied dependency expressed through constructor argument with index 0 of type [org.example.testapp.services.StringTransformer]: : No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean; nested exception is org.springframework.beans.factory.NoSuchBeanDefinitionException: No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean
[ERROR] Registry Operations trace:
[ERROR] Registry [ 1] Realizing service ServletApplicationInitializer
[ERROR] Registry [ 2] Invoking org.apache.tapestry5.services.TapestryModule.buildServletApplicationInitializer(Logger, List, ApplicationInitializer) (at TapestryModule.java:1031)
[ERROR] Registry [ 3] Constructing module class org.apache.tapestry5.services.TapestryModule
[ERROR] Registry [ 4] Determining injection value for parameter #1 (org.apache.tapestry5.ioc.services.PipelineBuilder)
[ERROR] Registry [ 5] Resolving object of type org.apache.tapestry5.ioc.services.PipelineBuilder using MasterObjectProvider
[ERROR] Registry [ 6] Resolving Spring bean of type org.apache.tapestry5.ioc.services.PipelineBuilder
[ERROR] Registry [ 7] Realizing service ApplicationContext
[ERROR] Registry [ 8] Invoking org.apache.tapestry5.internal.spring.SpringModuleDef$1$1@2cb491
[ERROR] Registry [ 9] Creating Spring Application Context
[ERROR] ApplicationContext Construction of service ApplicationContext failed: Error creating bean with name 'upcase' defined in ServletContext resource [/WEB-INF/applicationContext.xml]: Unsatisfied dependency expressed through constructor argument with index 0 of type [org.example.testapp.services.StringTransformer]: : No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean; nested exception is org.springframework.beans.factory.NoSuchBeanDefinitionException: No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean
org.apache.tapestry5.ioc.internal.OperationException: Error creating bean with name 'upcase' defined in ServletContext resource [/WEB-INF/applicationContext.xml]: Unsatisfied dependency expressed through constructor argument with index 0 of type [org.example.testapp.services.StringTransformer]: : No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean; nested exception is org.springframework.beans.factory.NoSuchBeanDefinitionException: No unique bean of type [org.example.testapp.services.StringTransformer] is defined: Unsatisfied dependency of type [interface org.example.testapp.services.StringTransformer]: expected at least 1 matching bean

That's a bit clearer, isn't it, as long as you realize what the MasterObjectProvider is ... and that we've contributed into it some code to resolve dependencies against the Spring ApplicationContext. In fact, what happened is that the test case failed because I haven't implemented a way for a Spring bean to receive a Tapestry service as an injection, and because Spring does not lazily initialize its beans by default, we see that failure immediately the first time we try to calculate an injection.