Apache Tapestry > Documentation > User Guide > IOC > Operation Tracker

Operation Tracker

Have you ever hit an error in some code and been faced with a giant stack trace, and no clue what that means?  Us too. We wished there was a way for the exception to describe the path to the error not (just) in terms of which methods called which methods, but what operations triggered what other operations. That's the OperationTracker.

The operation tracker is another aspect of Tapestry's commitment to feedback.

Related Articles

The OperationTracker is a resource; it's actually a singleton, and is available for injection into any IoC service (or Tapestry component).

Using the OperationTracker you may run a Runnable, or invoke an Invokable (returning a typed response).  Associated with the operation is a description string.

If there are no exceptions, then no problem.

If there  are exceptions, then you'll see the console output logged at the point of the exception:

qtp644826761-13 [ERROR] Registry Operations trace:qtp644826761-13 [ERROR] Registry [ 1] Handling page render request for page DatumEditorqtp644826761-13 [ERROR] Registry [ 2] Constructing instance of page class org.apache.tapestry5.integration.app1.pages.DatumEditorqtp644826761-13 [ERROR] Registry [ 3] Assembling root component for page DatumEditorqtp644826761-13 [ERROR] Registry [ 4] Running component class transformations on org.apache.tapestry5.integration.app1.pages.Datumqtp644826761-13 [ERROR] RequestExceptionHandler Processing of request failed with uncaught exception: java.lang.RuntimeException: Exception assembling root component of page DatumEditor: Unable to instantiate instance of transformed class org.apache.tapestry5.integration.app1.pages.DatumEditor: java.lang.reflect.InvocationTargetExceptionjava.lang.RuntimeException: Exception assembling root component of page DatumEditor: Unable to instantiate instance of transformed class org.apache.tapestry5.integration.app1.pages.DatumEditor: java.lang.reflect.InvocationTargetExceptionat org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.performAssembleRootComponent(ComponentAssemblerImpl.java:129)at org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.access$000(ComponentAssemblerImpl.java:37)at org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl$1.invoke(ComponentAssemblerImpl.java:81)at org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl$1.invoke(ComponentAssemblerImpl.java:78)at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:82)at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:72)at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:1258)at org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.assembleRootComponent(ComponentAssemblerImpl.java:76)at org.apache.tapestry5.internal.pageload.PageLoaderImpl$3.invoke(PageLoaderImpl.java:197)at org.apache.tapestry5.internal.pageload.PageLoaderImpl$3.invoke(PageLoaderImpl.java:190)at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.invoke(OperationTrackerImpl.java:82)at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.invoke(PerThreadOperationTracker.java:72)at org.apache.tapestry5.ioc.internal.RegistryImpl.invoke(RegistryImpl.java:1258)at org.apache.tapestry5.internal.pageload.PageLoaderImpl.loadPage(PageLoaderImpl.java:189)at $PageLoader_13a0346ec83c4e52.loadPage(Unknown Source)at org.apache.tapestry5.internal.services.PageSourceImpl.getPage(PageSourceImpl.java:104)at $PageSource_13a0346ec83c4e51.getPage(Unknown Source)at $PageSource_13a0346ec83c4e50.getPage(Unknown Source)at org.apache.tapestry5.internal.services.RequestPageCacheImpl.get(RequestPageCacheImpl.java:86)at $RequestPageCache_13a0346ec83c4e4f.get(Unknown Source)at $RequestPageCache_13a0346ec83c4e4e.get(Unknown Source)at org.apache.tapestry5.internal.services.PageRenderRequestHandlerImpl.handle(PageRenderRequestHandlerImpl.java:56)at org.apache.tapestry5.modules.TapestryModule$34.handle(TapestryModule.java:1978)at $PageRenderRequestHandler_13a0346ec83c4f9c.handle(Unknown Source)at $PageRenderRequestHandler_13a0346ec83c4f97.handle(Unknown Source)at org.apache.tapestry5.internal.services.ComponentRequestHandlerTerminator.handlePageRender(ComponentRequestHandlerTerminator.java:48)at org.apache.tapestry5.internal.services.DeferredResponseRenderer.handlePageRender(DeferredResponseRenderer.java:52)at $ComponentRequestFilter_13a0346ec83c4f95.handlePageRender(Unknown Source)at $ComponentRequestHandler_13a0346ec83c4f98.handlePageRender(Unknown Source)at org.apache.tapestry5.services.InitializeActivePageName.handlePageRender(InitializeActivePageName.java:47)at $ComponentRequestFilter_13a0346ec83c4f94.handlePageRender(Unknown Source)at $ComponentRequestHandler_13a0346ec83c4f98.handlePageRender(Unknown Source)at org.apache.tapestry5.internal.services.ProductionModeUnknownComponentFilter.handlePageRender(ProductionModeUnknownComponentFilter.java:62)at $ComponentRequestFilter_13a0346ec83c4f93.handlePageRender(Unknown Source)at $ComponentRequestHandler_13a0346ec83c4f98.handlePageRender(Unknown Source)at org.apache.tapestry5.internal.services.RequestOperationTracker$2.run(RequestOperationTracker.java:73)at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:56)at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.run(PerThreadOperationTracker.java:60)at org.apache.tapestry5.ioc.internal.RegistryImpl.run(RegistryImpl.java:1252)at org.apache.tapestry5.internal.services.RequestOperationTracker.handlePageRender(RequestOperationTracker.java:66)at $ComponentRequestFilter_13a0346ec83c4f92.handlePageRender(Unknown Source)at $ComponentRequestHandler_13a0346ec83c4f98.handlePageRender(Unknown Source)at $ComponentRequestHandler_13a0346ec83c4f81.handlePageRender(Unknown Source)at org.apache.tapestry5.internal.services.PageRenderDispatcher.dispatch(PageRenderDispatcher.java:52)at $Dispatcher_13a0346ec83c4f7f.dispatch(Unknown Source)at $Dispatcher_13a0346ec83c4f80.dispatch(Unknown Source)at $Dispatcher_13a0346ec83c4f74.dispatch(Unknown Source)at org.apache.tapestry5.modules.TapestryModule$RequestHandlerTerminator.service(TapestryModule.java:304)at org.apache.tapestry5.internal.services.RequestErrorFilter.service(RequestErrorFilter.java:26)at $RequestFilter_13a0346ec83c4f73.service(Unknown Source)at $RequestHandler_13a0346ec83c4f75.service(Unknown Source)at org.apache.tapestry5.modules.TapestryModule$3.service(TapestryModule.java:854)at $RequestHandler_13a0346ec83c4f75.service(Unknown Source)at org.apache.tapestry5.modules.TapestryModule$2.service(TapestryModule.java:844)at $RequestHandler_13a0346ec83c4f75.service(Unknown Source)at org.apache.tapestry5.internal.services.StaticFilesFilter.service(StaticFilesFilter.java:89)at $RequestHandler_13a0346ec83c4f75.service(Unknown Source)at org.apache.tapestry5.integration.app1.services.AppModule$2.service(AppModule.java:111)at $RequestFilter_13a0346ec83c4f71.service(Unknown Source)at $RequestHandler_13a0346ec83c4f75.service(Unknown Source)at $RequestHandler_13a0346ec83c4f6a.service(Unknown Source)at org.apache.tapestry5.modules.TapestryModule$HttpServletRequestHandlerTerminator.service(TapestryModule.java:255)at org.apache.tapestry5.internal.gzip.GZipFilter.service(GZipFilter.java:59)at $HttpServletRequestHandler_13a0346ec83c4f6c.service(Unknown Source)at org.apache.tapestry5.internal.services.IgnoredPathsFilter.service(IgnoredPathsFilter.java:62)at $HttpServletRequestFilter_13a0346ec83c4f6d.service(Unknown Source)at $HttpServletRequestFilter_13a0346ec83c4f68.service(Unknown Source)at $HttpServletRequestHandler_13a0346ec83c4f6c.service(Unknown Source)at org.apache.tapestry5.modules.TapestryModule$1.service(TapestryModule.java:804)at $HttpServletRequestHandler_13a0346ec83c4f6c.service(Unknown Source)at $HttpServletRequestHandler_13a0346ec83c4f67.service(Unknown Source)at org.apache.tapestry5.TapestryFilter.doFilter(TapestryFilter.java:166)at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1291)at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:443)at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:556)at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:227)at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1044)at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:372)at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:189)at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:978)at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)at org.eclipse.jetty.server.Server.handle(Server.java:369)at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:486)at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:933)at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:995)at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)at java.lang.Thread.run(Thread.java:724)Caused by: java.lang.RuntimeException: Unable to instantiate instance of transformed class org.apache.tapestry5.integration.app1.pages.DatumEditor: java.lang.reflect.InvocationTargetExceptionat org.apache.tapestry5.internal.plastic.ClassInstantiatorImpl.newInstance(ClassInstantiatorImpl.java:113)at org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl$2$1.newInstance(ComponentInstantiatorSourceImpl.java:235)at org.apache.tapestry5.internal.structure.InternalComponentResourcesImpl.<init>(InternalComponentResourcesImpl.java:163)at org.apache.tapestry5.internal.structure.ComponentPageElementImpl.<init>(ComponentPageElementImpl.java:555)at org.apache.tapestry5.internal.structure.ComponentPageElementImpl.<init>(ComponentPageElementImpl.java:579)at org.apache.tapestry5.internal.pageload.ComponentAssemblerImpl.performAssembleRootComponent(ComponentAssemblerImpl.java:97)... 94 moreCaused by: java.lang.reflect.InvocationTargetExceptionat sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)at java.lang.reflect.Constructor.newInstance(Constructor.java:526)at org.apache.tapestry5.internal.plastic.ClassInstantiatorImpl.newInstance(ClassInstantiatorImpl.java:109)... 99 moreCaused by: org.apache.tapestry5.ioc.internal.OperationException: Field _value of class org.apache.tapestry5.integration.app1.pages.Datum must be instrumented, and may not be public.at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.logAndRethrow(OperationTrackerImpl.java:184)at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:62)at org.apache.tapestry5.ioc.internal.PerThreadOperationTracker.run(PerThreadOperationTracker.java:60)at org.apache.tapestry5.ioc.internal.RegistryImpl.run(RegistryImpl.java:1252)at org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl.transform(ComponentInstantiatorSourceImpl.java:266)at org.apache.tapestry5.internal.plastic.PlasticClassPool.loadAndTransformClass(PlasticClassPool.java:368)at org.apache.tapestry5.internal.plastic.PlasticClassLoader.loadClass(PlasticClassLoader.java:38)at java.lang.ClassLoader.loadClass(ClassLoader.java:357)at org.apache.tapestry5.integration.app1.pages.DatumEditor.initializeInstance(DatumEditor.java:22)at org.apache.tapestry5.integration.app1.pages.DatumEditor.<init>(DatumEditor.java)... 104 moreCaused by: java.lang.IllegalArgumentException: Field _value of class org.apache.tapestry5.integration.app1.pages.Datum must be instrumented, and may not be public.at org.apache.tapestry5.internal.plastic.PlasticFieldImpl.ensureNotPublic(PlasticFieldImpl.java:166)at org.apache.tapestry5.internal.plastic.PlasticFieldImpl.replaceFieldReadAccess(PlasticFieldImpl.java:423)at org.apache.tapestry5.internal.plastic.PlasticFieldImpl.setComputedConduit(PlasticFieldImpl.java:292)at org.apache.tapestry5.internal.transform.UnclaimedFieldWorker.transformField(UnclaimedFieldWorker.java:99)at org.apache.tapestry5.internal.transform.UnclaimedFieldWorker.transform(UnclaimedFieldWorker.java:88)at $ComponentClassTransformWorker2_13a0346ec83c4e9a.transform(Unknown Source)at $ComponentClassTransformWorker2_13a0346ec83c4e9c.transform(Unknown Source)at $ComponentClassTransformWorker2_13a0346ec83c4e7f.transform(Unknown Source)at org.apache.tapestry5.internal.services.ComponentInstantiatorSourceImpl$3.run(ComponentInstantiatorSourceImpl.java:316)at org.apache.tapestry5.ioc.internal.OperationTrackerImpl.run(OperationTrackerImpl.java:56)... 112 more




Notice how the operation trace at the top of the text succinctly explains how execution arrived at the point of failure and why, information that isn't captured in a stack trace.
This operation trace appears in the Tapestry web applications, as part of the default exception report page.
There are times, especially when tracking down startup failures, where it is useful to see the operations log even without explicit exceptions.
Enabling debug level logging for the org.apache.tapestry5.ioc.Registry logging category will provide huge volumes of output in the console:
[DEBUG] Registry [ 1] --> Creating non-proxied instance of service ServiceConfigurationListenerHub[DEBUG] Registry [ 2] --> Creating plan to instantiate org.apache.tapestry5.ioc.services.ServiceConfigurationListenerHub via public org.apache.tapestry5.ioc.services.ServiceConfigurationListenerHub(java.util.List)[DEBUG] Registry [ 3] --> Determining injection value for parameter #1 (java.util.List)[DEBUG] Registry [ 4] --> Collecting ordered configuration for service ServiceConfigurationListenerHub[DEBUG] Registry [ 5] --> Invoking org.apache.tapestry5.ioc.FredModule.configureServiceConfigurationListener(OrderedConfiguration, CatchAllServiceConfigurationListener) (at FredModule.java:141)[DEBUG] Registry [ 6] --> Determining injection value for parameter #1 (org.apache.tapestry5.ioc.OrderedConfiguration)[DEBUG] Registry [ 6] <-- Determining injection value for parameter #1 (org.apache.tapestry5.ioc.OrderedConfiguration) [0.17 ms][DEBUG] Registry [ 6] --> Determining injection value for parameter #2 (org.apache.tapestry5.ioc.CatchAllServiceConfigurationListener)[DEBUG] Registry [ 7] --> Creating proxy for service MasterObjectProvider[DEBUG] Registry [ 7] <-- Creating proxy for service MasterObjectProvider [2.82 ms][DEBUG] Registry [ 7] --> Realizing service MasterObjectProvider[DEBUG] Registry [ 8] --> Instantiating service MasterObjectProvider implementation via org.apache.tapestry5.ioc.internal.services.MasterObjectProviderImpl(List, OperationTracker) (at MasterObjectProviderImpl.java:33) via org.apache.tapestry5.ioc.modules.TapestryIOCModule.bind(ServiceBinder) (at TapestryIOCModule.java:50)[DEBUG] Registry [ 9] --> Creating plan to instantiate org.apache.tapestry5.ioc.internal.services.MasterObjectProviderImpl via public org.apache.tapestry5.ioc.internal.services.MasterObjectProviderImpl(java.util.List,org.apache.tapestry5.ioc.OperationTracker)[DEBUG] Registry [ 10] --> Determining injection value for parameter #1 (java.util.List)[DEBUG] Registry [ 11] --> Collecting ordered configuration for service MasterObjectProvider[DEBUG] Registry [ 12] --> Invoking org.apache.tapestry5.ioc.modules.TapestryIOCModule.setupObjectProviders(OrderedConfiguration, ServiceOverride) (at TapestryIOCModule.java:136)[DEBUG] Registry [ 13] --> Determining injection value for parameter #1 (org.apache.tapestry5.ioc.OrderedConfiguration)[DEBUG] Registry [ 13] <-- Determining injection value for parameter #1 (org.apache.tapestry5.ioc.OrderedConfiguration) [0.17 ms][DEBUG] Registry [ 13] --> Determining injection value for parameter #2 (org.apache.tapestry5.ioc.services.ServiceOverride)[DEBUG] Registry [ 14] --> Creating proxy for service ServiceOverride[DEBUG] Registry [ 14] <-- Creating proxy for service ServiceOverride [2.15 ms][DEBUG] Registry [ 13] <-- Determining injection value for parameter #2 (org.apache.tapestry5.ioc.services.ServiceOverride) [2.62 ms][DEBUG] Registry [ 13] --> Creating proxy for service UpdateListenerHub[DEBUG] Registry [ 13] <-- Creating proxy for service UpdateListenerHub [2.28 ms]
...




The output identifies operation depth (the number in square brackets), whether the operation is starting (–>) or finishing (<–), and even the execution time of the operation.