Dissecting a Tapestry Operation Trace

I'm helping out a client who is having a problem using Spock and Tapestry 5.3 together. The Spock/Tapestry integration was created for Tapestry 5.2, and some subtle change in the Tapestry 5.3 IoC container has boned the integration, so running even a simple test results in an exception, with a very big stacktrace:

The part at the top (the numbered entries) are the operation trace: Tapestry tracks what its doing at all times (using a stack stored inside a ThreadLocale) just so it can report this information in case there's an error. That's part of Tapestry's commitment to useful feedback. The operation tracing was enhanced a bit in Tapestry 5.3 to be a bit more verbose and all-reaching.

The operation trace is providing a wealth of information about how Tapestry got to the point where an exception was thrown. This is much more useful than just the huge stack trace (about 400 frames!) since Tapestry, by design, tends to call through the very same methods repeatedly; stack traces are less useful when what counts are the parameters to the methods, rather than the methods themselves.

It takes a while to figure out, but the key operations are:

That operation corresponds to invoking this method:

Translated to English, this code says:

When starting up the Registry (the odd name for the Tapestry IoC container), execute this block of code, that checks to see if early startup of Hibernate is desired and, if so, forces the initialization of Hibernate by invoking the getConfiguration() method (otherwise, the initialization would happen lazily the first time a request needed to use the Hibernate Session).

The @Symbol annotation means that the parameter's value is derived from a Tapestry configuration symbol, which is a flexible, late-binding way to configure services as they are instantiated. In other words, because of the use of a symbol, rather than a constant, the actual value passed in can't be determined until runtime ... which is a good thing; it means a developer can configure the symbol's value locally, but a different default value is in effect for the production application. Sometimes you want early startup, sometimes you don't.

In order to resolve the value of a symbol, Tapestry must instantiate the SymbolSource service; it has its own configuration that depends on other services, including ApplicationDefaults, FactoryDefaults, as well as a few other simple objects that implement the SymbolProvider interface, but are not services.

There's also a hidden dependency here: Starting in Tapestry 5.3, Tapestry will attempt to type-coerce contributed values (in this case, symbol values contributed to ApplicationDefaults or FactoryDefaults) from their actual type, to the expected type. That shows up in operation 14:

Those integers and booleans need to be converted to Strings; Tapestry 5.3 invokes the full machinery of the TypeCoercer service to do this coersion, seen as operation 15.

At operations 21 - 23, Tapestry sees the ThreadLocale service (which stores the active Locale used during processing of the request; something that can vary on a request-by-request basis). The ThreadLocale service uses a special service lifecycle that enforces that the instance is stored as a per-thread singleton, not a per-Registry singleton, and will be discarded at the end of each request.

The ServiceLifecycleSource service is the source for these ServiceLifecycle objects.

At operation 28 - 31, the Spock/Tapestry integration code is getting involved. It adds a special service lifecycle just for values that are part of a Spock specification ... and we're finally reaching the problem point!

The Spock/Tapestry integration is using the addInstance() method, which instantiates a class with dependencies; this is operation 30. This is the problem point, but it's not obvious why its causing an eventual exception.

Because of the use of addInstance(), Tapestry must locate and inject the dependencies of the PerIterationServiceLifecycle class, including the IPerIterationManager service (operation 31).

In Tapestry, there is a mechanism to replace services with overrides; this is the ServiceOverride service and its configuration. It's super handy for extending Tapestry in completely unexpected ways.

That brings us to some code, new in Tapestry 5.3, at operation 38:

And that brings us to the actual cause. Notice the @Symbol annotation ... remember way back to operation 7, that required the TypeCoercer (operation 15) ... well, we're not done with that yet, but this production override code has a @Symbol annotation that requires the TypeCoercer ... which is still in the middle of being instantiated.

Yes, this takes a lot of detective work ... this is something of an Achilles' Heel of Tapestry's IoC container; since much of the functionality of the container is defined in terms of other functionality of the container, you can get into these hidden dependency cycles when tweaking some of the more fundamental aspects of Tapestry, such as TypeCoercer contributions, or adding new service lifecycles. This is unfortunate, since so much else in Tapestry's web framework and IoC container Just Works^TM.

In terms of fixing this ... turns out the Spock/Tapestry integration has some other dependencies on 5.2, making use of internal classes and constructors that no longer exist in 5.3. I'll be forking their code shortly to produce a 5.3 compatible version.

However, my take-away here is: the system works, the emphasis on feedback, and the generation of useful operation traces, makes this detective work even possible. The alternative would have taken far, far longer ... using the debugger to try and work backwards to what Tapestry was trying to do. It's so much better to have Tapestry simply tell you what you need to know!