The versioning isn’t happening, part 1: wanderings

This post is part 1 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 2: beforeCompletion.


We have a .war project that uses envers to update a revision table when a record is created, updated, or deleted in a certain table.

0. The Problem

When the project is deployed configured to connect to a Hibernate transaction manager:

<bean id="transactionManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
<property name="sessionFactory" ref="sessionFactory" />
</bean>

then when I make the web service call that results in a record being written to the database, the envers versioning records are also created; but when the project is deployed configured to connect to the JTA transaction manager:

<tx:jta-transaction-manager />

the envers versioning records are not created.

Following are some steps I took, in a simplified ordering. (I actually jumped back and forth a lot more between debugging in Eclipse and setting up to examine log output).  I’ve left out a lot of the running around in circles and some of the dead ends.  :)

1. The Sanity Check

At the envers user forum, I inquired whether envers is known to work with a JTA; and a kind soul replied that they’re using envers with JTA and it’s working fine for them.

2. Using Log messages

I added this to jboss-log4j.xml:

<logger name="org.hibernate.jdbc">
<level value="TRACE" />
<appender-ref ref="HibernateLog" />
</logger>

<logger name="org.hibernate.transaction">
<level value="TRACE" />
<appender-ref ref="HibernateLog" />
</logger>

When I compared the JBoss server.log files after testing my web-service-call-that-writes-a-record-to-the-database using a JTA transaction manager versus using the Hibernate transaction manager, I noticed that the JTA version doesn’t seem to make use of the org.hibernate.transaction.JDBCTransaction class.

3. The Helpfulness of Java Search

I wondered, what code is responsible for choosing where the JDBCTransaction class is used?  I wanted to do a search that included the source attachments in my project’s Referenced Libraries, but Eclipse’s File Search (the search I use for everything) didn’t seem to do that.  So I tried the Java Search tab, searching for

  • Search string: org.hibernate.transaction.JDBCTransaction
  • Search For: Type
  • Limit To: References
  • Search In: Sources, Required projects, JRE libraries, Application libraries
  • Scope: Workspace

and lo and behold, it searched in the referenced libraries and found two places that reference JDBCTransaction:

  • org.hibernate.transaction.JDBCTransactionFactory in hibernate-3.2.6.ga.jar
  • org.springframework.orm.hibernate3.SpringTransactionFactory in spring-orm-2.5.5.jar

4. Breakpoints

I put a class load breakpoint on each of these classes, and deployed the Hibernate version of the project, my guess being that the problem may be occurring before the first message is sent, when the project is being deployed and setting up with the transaction manager.

5. Who loaded me?

I brought JBoss-with-remote-debugging up and hit the class load breakpoint for the SpringTransactionFactory.  Not recognizing where the call was coming from (it was being invoked via reflection), I went to the Outline view, selected all the methods of SpringTransactionFactory including its constructor, set method entry breakpoints, and resumed.  This time it hit org.hibernate.transaction.TransactionFactoryFactory.buildTransactionFactory(), called from org.hibernate.cfg.SettingsFactory.buildSettings(), which is called from org.springframework.orm.hibernate3.LocalSessionFactoryBean.newSessionFactory().

6. Wonderings

Hmm, I bet the hibernate3.LocalSessionFactoryBean is not used when we’re in JTA mode.  I put class load breakpoints on TransactionFactoryFactory, SettingsFactory, and LocalSessionFactoryBean to see if any of these are used when we’re in jta mode.

7. Trying it in JTA mode

The first breakpoint we hit in jta mode is during the creation of the sessionFactory bean.  And… huh, at this point we are in org.springframework.orm.hibernate3.LocalSessionFactoryBean.buildSessionFactory().  The newSessionFactory() call is at the bottom of this method… let’s see if we make it down there in JTA mode.

Hmm, this.jtaTransactionManager is null on line 524 in LocalSessionFactoryBean… (I don’t know if that’s good or bad…)

org.springframework.orm.hibernate3.AbstractSessionFactoryBean.isExposeTransactionAwareSessionFactory() returns true on line 550 — I wonder if that was the case in Hibernate mode? — this results in the hibernate.current_session_context_class property being set in the AnnotationConfiguration being built.

8. Trying it in Hibernate mode

I deployed the Hibernate version of my .war project, and…

  • org.springframework.orm.hibernate3.AbstractSessionFactoryBean.isExposeTransactionAwareSessionFactory() does return true on line 550 just like in jta mode.
  • When I examine the AnnotationConfiguration named config‘s properties field (In org.springframework.orm.hibernate3.LocalSessionFactoryBean’s buildSessionFactory() where the AnnotationConfiguration is done being built) and compare its contents to when I run in jta mode… they’re identical except for one property:
    < jboss.remoting.jmxid=hostname_1228281077636

    > jboss.remoting.jmxid=hostname_1228281368304

So, I still haven’t discovered the source of the difference between the Hibernate and JTA modes.

Perhaps next I should capture the values of the rest of AnnotationConfiguration’s 47 fields, and compare them all between jta mode and Hibernate mode.  (I somehow didn’t expect the properties to be the same…!)

Advertisements

Applying advice based on type

When we add JMS queue support to our architecture, we’ll want to apply some AOP advice each time a listener receives a message.  We want to have a convention for how the listeners will be set up so that our advice will find them.

In a recent communication with the design leads, I proposed that one of the ways we recognize a MessageListener be by having a convention that its class name must be *MessageListener.

One of the design leads asked a great question: Could we go based on the class implementing the MessageListener interface instead of being named a certain way?  That would be slick, wouldn’t it?  I didn’t know the answer, though.  I only knew about matching based on name of the class/package/method/signature.

Starting

Too much advice

This pointcut expression works, but applies to too much:

execution(void com.ontsys..svc..*.onMessage(..))

We want to modify it to only apply to classes that implement the javax.jms.MessageListener interface.

Trying

A ineffectual plus

At first it looked like the plus sign was what we needed.  The AspectJTM Programming Guide Appendix B. Language Semantics: Type patterns section on Subtype patterns says:

It is possible to pick out all subtypes of a type (or a collection of types) with the “+” wildcard. The “+” wildcard follows immediately a type name pattern.

And the Spring manual contains an example of the + wildcard on an execution pointcut.

My first attempt was a misuse of the plus sign, though I didn’t know it right away:

execution(void com.ontsys..svc..MessageListener+.onMessage(..)

That didn’t work– when I deployed the project, the advice wasn’t applied to my listener. (I could tell because the listener relies on something the AOP advice sets up, and it blew up when that wasn’t there.)

I see now that I was misusing the plus operator — I wanted the advice to apply to any implementor/subclass of javax.jms.MessageListener, but the way I was using it it was as if I was trying to have the advice apply to any implementor/subclass of com.ontsys..svc..MessageListener.

Escaping from the Ampersands

The Spring manual’s AOP pointcut examples section shows an example using “target”:

target(com.xyz.service.AccountService)

and says it matches “any join point (method execution only in Spring AOP) where the target object implements the AccountService interface”

I tried this:

execution(void com.ontsys..svc..*.onMessage(..)) && target(MessageListener)

On deployment, though, I got an error about one of the ampersands…

And…

I modified the pointcut expression to use the word and instead:

execution(void com.ontsys..svc..*.onMessage(..)) and target(MessageListener)

Now I got this error:

warning no match for this type name: MessageListener [Xlint:invalidAbsoluteTypeName]

Success

Noticing that the Spring manual’s AOP pointcut examples all seemed to show fully-qualified types, I thought I’d try fully qualifying the name of the MessageListener interface:

execution(void com.ontsys..svc..*.onMessage(..)) and target(javax.jms.MessageListener)

This one worked. Woohoo!

Maybe I’m on my way to being a fully-qualified pointcut-expression writer.  :D

Customizing log4j logging on JBoss

I want to turn up the logging level on JBoss so that I can verify that the transactional AOP advice runs before the Spring-security-context-populatin’ advice.  The reason being, I want to make sure we’re already in a transaction if something goes wrong in the security context advice, so the message will get rolled back onto the queue.

To be more precise, I want to turn up the logging level on the right categories of classes — my server/default/log/server.log is already 190MB today, and Notepad and Eclipse are having trouble opening it.

The Packages I want to log about

For the first round, I want to see DEBUG-level messages for my Spring-security-context-populatin’ advice (the com.ontsys.advice package in my prototype) and the org.springframework.transaction.jta package.

Adding Logging to my Class

First, I need to add logging to my class — it currently doesn’t log any messages.

Adding logging to a class is simple:

import org.apache.log4j.Logger;
public class MyClass {
    private static final Logger LOGGER = Logger.getLogger(MyClass.class); 

    public void decombobulate() {
        LOGGER.debug("Decombobulating...");
        //...
    }
}

Configuring jboss-log4j.xml

The Logging Conventions chapter of the JBoss Development Process Guide (see also the Logging page on the JBoss Wiki) explains how to log certain categories to a different file.

Only instead of  ${jboss.server.home.dir}/log/ I’ll use more elegant ${jboss.server.log.dir}/ .

Everything in its Proper Place

Note that according to the log4j 1.2.15 DTD, the elements have to be ordered with all appenders first, followed by categories, and then the root element:

<!ELEMENT log4j:configuration (renderer*, appender*,plugin*, (category|logger)*,root?,
                               (categoryFactory|loggerFactory)?)>

Additivity

Note also that there is an additivity attribute you can use on the on the appenders.  The section called Redirecting Category Output has this to say about the additivity attribute:

The additivity attribute controls whether output continues to go to the root category appender. If false, output only goes to the appenders referred to by the category.

That would explain why my main server/default/log/server.log was so small the other time I tried adding a category appender — I think I had additivity=”false” from an example configuration I found somewhere, without understanding what it meant — so output that was going to my special log file was no longer going to my server.log file.

The DTD says that the additivity attribute defaults to “true” though, which is what I want, so I’m leaving it out.

My Changes to jboss-log4j.xml

Here’s what I eventually came up with:

<appender name="AdviceLog" class="org.apache.log4j.FileAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler" />
<param name="Append" value="false" />
<param name="File" value="${jboss.server.log.dir}/advice.log" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %-5p &#91;%c&#93; %m%n" />
</layout>
</appender>
...
<category name="com.ontsys.advice">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />
</category>
<category name="org.springframework.transaction.jta">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />
</category>

Success

This worked great!  Only stuff from the com.ontsys.advice and org.springframework.transaction.jta packages in the advice.log, at the DEBUG level.

For Next Time

At first the advice.log file was getting way too much information… but we’ll stop here for the moment!

JMX meets the DefaultMessageListenerContainer

(It’s kind of like King Kong vs. Godzilla, only more peaceful)

According to the Javadoc, these properties on the DefaultMessageListenerContainer “can be modified at runtime, for example through JMX” :

concurrentConsumers
maxConcurrentConsumers
maxMessagesPerTask
idleTaskExecutionLimit

Armed with this and my handy Spring manual, I added the following to my beans file:


    <bean id="exporter" class="org.springframework.jmx.export.MBeanExporter" lazy-init="false">
<property name="beans">
            <map>
                <entry key="bean:name=listenerContainer1" value-ref="listenerContainer" />
            </map>
        </property>
    </bean>

(In this beans file I already had a DefaultMessageListenerContainer bean with an id of listenerContainer.)

Now when I fired up my JBoss JMX Management, a new bean category appears:

I can click on that link and see several properties that I can change on the DefaultMessageListenerContainer bean, including ConcurrentConsumers, which is currently 1.  If I change that to 2 and press the Apply Changes button though, I get a stack trace in JBoss:

12:47:17,978 ERROR [[HtmlAdaptor]] Servlet.service() for servlet HtmlAdaptor threw exception java.lang.ClassNotFoundException: org.springframework.jms.support.destination.DestinationResolver

So we’ll have to figure out what that’s about.

The mysteriously necessary sessionTransacted=true

I’ve encountered this before, but just ran into it again: Despite suggestions to the contrary, it is necessary (at least with Spring 2.5.5, ActiveMQ 5.1.0, and JBoss 4.2.2.GA) to set sessionTransacted=true in the DefaultMessageListenerContainer even when it’s set up to connect to an external JTA transaction manager. If I set sessionTransacted=true, then when my messageListener throws a RuntimeException, the message is rolled back onto the queue; if I don’t, it doesn’t.

This has been documented elsewhere regarding Atomikos, but not ActiveMQ. I’ve posted a question to the Spring Remoting and JMS forum. We’ll see what comes of it!

Who did you say you were?

Sometimes you want authentication — you don’t want to let a connection in to your system unless it supplies the right credentials.  Other times, you just want identification — for instance, you might want to remember who it was that initiated a request.

One example of this distinction is when you’re dealing with JMS queues.  The process that puts a message in a queue may have been involved in authenticating the user… but the process that takes that message out of the queue to process may not have been.  That receiving process needs a way to identify the user that placed the message in the queue.

The first part of the solution is to pass the userId along with the JMS message, to the queue.  You can do this by setting a String property on the JMS Message.

Before we can use LDAP to look up information about this user, though, we need to populate the Spring security context with this userId.  (Spring does support setting the SecurityContextHolder contents directly.)  So that the domain-level developers don’t have to worry about this, we can use AOP around-advice, like this:


    public Object doPopulateSecurityContext(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        Message message = (Message) proceedingJoinPoint.getArgs()[0];
        String userId = message.getStringProperty("userId");
        UsernamePasswordAuthenticationToken authenticationToken = new UsernamePasswordAuthenticationToken(userId, "");
        SecurityContext context = new SecurityContextImpl();
        context.setAuthentication(authenticationToken);
        SecurityContextHolder.setContext(context);

        Object retVal = proceedingJoinPoint.proceed();

        SecurityContextHolder.clearContext();
        return retVal;
    }

This populates the information about the current user so that the MessageListener can look up things in LDAP based on that.

The Little Integration Test that Didn’t: part 1

Our system is set up to automagically wrap each call coming into the service layer in a transaction (using AOP transaction advice), automatically committing the transaction if the call completes normally and automatically rolling back the transaction if an exception is thrown… a RuntimeException or Error, that is.

Rolling back on RuntimeException or Error but not on a (checked) Exception is Spring’s default behavior:

Note however that the Spring Framework’s transaction infrastructure code will, by default, only mark a transaction for rollback in the case of runtime, unchecked exceptions; that is, when the thrown exception is an instance or subclass of RuntimeException. (Errors will also – by default – result in a rollback.) Checked exceptions that are thrown from a transactional method will not result in the transaction being rolled back.

Exactly which Exception types mark a transaction for rollback can be configured.

(from the Rolling Back section of the Transaction Management chapter of the Spring 2.5 Manual)

Battling Assumptions

While we framework guys assumed that any exceptions thrown would extend RuntimeException, the application guys didn’t share our assumption.  Their assumption was, “If an exception is thrown, the transaction rolls back.”  So the question was, should the transaction advice be changed to also apply to checked exceptions, or should the application-level exceptions be changed to extend RuntimeException?

Seems Ok to Change from Spring’s Default

I thought perhaps it was for some reason a bad idea to change this default rollback behavior — that perhaps there was an important reason Spring did it this way.  But a quick look at the Spring manual told me otherwise:

While the EJB default behavior is for the EJB container to automatically roll back the transaction on a system exception (usually a runtime exception), EJB CMT does not roll back the transaction automatically on an application exception (that is, a checked exception other than java.rmi.RemoteException). While the Spring default behavior for declarative transaction management follows EJB convention (roll back is automatic only on unchecked exceptions), it is often useful to customize this.

(from the Declarative Transaction Management section of the Spring 2.5 Manual)

Changing our Advice

There being no blockage from that quarter and not being able to think of a good reason why we’d want to commit our transactions when a checked exception was thrown, we changed our transactional advice bean from this:


    <tx:advice id="txAdvice" transaction-manager="transactionManager">
        <tx:attributes>
            <tx:method name="*" />
        </tx:attributes>
    </tx:advice>

to this:


    <tx:advice id="txAdvice" transaction-manager="transactionManager">
        <tx:attributes>
            <tx:method name="*" rollback-for="Exception"/>
        </tx:attributes>
    </tx:advice>

And, after some fits and starts, the integration test showed that transactions were rolling back for RuntimeException, Error, and Exception.  (Why the fits and starts?  That explanation will have to wait till next time.)

Wiring a web service

I’m dabbling in web services setup, not really knowing what I’m doing yet, and here’s a situation I encountered today:

I was taking a prior example where the web service setup had been done for me, and adapting it for use with a new prototype. I had a WEB-INF/services.xml that looked like this:

<beans xmlns="http://www.springframework.org/schema/beans" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:amq="http://activemq.org/config/1.0" xmlns:jaxws="http://cxf.apache.org/jaxws"
	xmlns:http-conf="http://cxf.apache.org/transports/http/configuration"
	xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
		http://cxf.apache.org/transports/http/configuration http://cxf.apache.org/schemas/configuration/http-conf.xsd
		http://cxf.apache.org/jaxws http://cxf.apache.org/schemas/jaxws.xsd
		http://activemq.org/config/1.0 http://activemq.apache.org/schema/core/activemq-core-5.0.0.xsd"
	default-autowire="no">

	<import resource="classpath:META-INF/cxf/cxf.xml" />
	<import resource="classpath:META-INF/cxf/cxf-extension-soap.xml" />
	<import resource="classpath:META-INF/cxf/cxf-servlet.xml" />

	<jaxws:endpoint id="myGreetingSvcEndpoint" implementor="#myGreetingSvc" address="/GreetingSvc" />

	<bean id="greetingSvc" class="com.example.svc.GreetingSvcImpl">
<property name="messageSender" ref="messageSender" />
	</bean>
</beans>

When I tried deploying this though, it was looking for a myGreetingSvc bean and couldn’t find it:

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'myGreetingSvcEndpoint': Cannot resolve reference to bean 'myGreetingSvc' while setting constructor argument; nested exception is org.springframework.beans.factory.NoSuchBeanDefinitionException: No bean named 'myGreetingSvc' is defined
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java
...
Caused by: org.springframework.beans.factory.NoSuchBeanDefinitionException: No bean named 'myGreetingSvc' is defined

Why would it be looking for a myGreetingSvc bean?  It seems that the implementor attribute of the jaxws:endpoint expects to reference a bean — replacing “#myGreetingSvc” with “#greetingSvc” on line 14 in services.xml (and correcting my @WebService annotation’s endpointInterface property in GreetingSvcImpl.java to match the name of the interface it was trying to point to) got it working.

I think a lot of how our service.xml is set up (how it’s Spring-like) is because we’re also using CXF, which I hear is Spring-aware.  There’s a lot I still don’t know about web services!

The convenience of going back in time

Eclipse has a really nice feature called “Local History”.  Allow me to demonstrate how it helped me just now:

We have a TransactionManager class that provides the ability for writers of integration tests who are writing tests below the level where AOP transaction advice is automatically applied, to just do basic getTransaction(), commit() and rollback() operations without worrying about the details of the underlying Spring PlatformTransactionManager.

Once you instantiate our TransactionManager, it holds a reference to the PlatformTransactionManager bean.

It’s possible for a test writer to have a situation where they reinitialize the Spring application context but are still holding onto a PlatformTransactionManager bean reference from the prior instantiation.  These developers don’t tend to focus their energies on such low-level issues like we Framework guys do, so it could be quite a time-waster if it resulted in an obscure error they had to debug to get to the root of — we’d rather detect the situation and throw a more descriptive error.

To that end, I had started yesterday morning writing a test that would show what currently happens in this scenario, in preparation for changing the code to do the detect-n-throw.

After this start though, I spent most of the day doing training.   It was fun!  But an interesting thing about doing interactive training with code examples: by the time it was all done, my Eclipse workspace was in quite an odd state!  Tests failing, things not compiling — because in the process of explaining I would just go try things here and there.  Afterward, the best thing to do was just revert everything back to what was in the repository.

Today I looked at my test class for the TransctionManager and noticed that my work on the scenario I’ve described was gone.  “Ah yes, I reverted the source…” I mused.  I started to type it in again, but it required enough thinking about what calls the mocks should expect, that I hesitated, and remembered Local History.

Local history records a snapshot each time you save, and I save changes so often that a lot of times it’s hard to find just the local revision I need…

I decided to try it anyway.  I right-clicked on my TransactionManagerTest and chose Compare With -> Local History…

This added the History view, and I expanded Yesterday…

Notice the several saves leading up to 8:49 AM, and then the lone change at 3:16 PM.  3:16 PM looks like the revert, so let’s double-click on the 8:49 AM one to compare…

(The whitish bars along the right-hand side show where differences are.  Bigger changes show up as bigger whitish bars.  I clicked on the largish bar near the bottom.)

This is the method I coded yesterday!  Let’s put it back in the source: while it’s selected, press the “Copy Current Change from Right to Left” button, and…

There we are…beautiful!