Why envers was blowing up

We’re experiencing an issue when we try to use envers to version a persistent object that holds a set of other persistent objects, when we’re using Spring’s JTA transaction manager.  (It doesn’t happen when we use hibernate local transactions using Spring’s HibernateTransactionManager.)  The commit of a one-to-many relationship (a Product and a Product Set), blows up with a weird error.

I had made a little test project with a greeting and a greeting set, to try to duplicate the issue apart from all the domain code.  I was not able to duplicate the issue — my greeting and greeting set committed fine, and the versioning records were created normally.

My test was set up like this:

    /**
     * This test commits an empty greeting set, then commits a new greeting to the set.      * The envers versioning works. 
     */
    @Test
    public void testSimpleCreate() {
        final String greeting = "Hola";
        assertNull(greetingDao.findByGreeting(greeting));

        final String setName = "Saludos";
        GreetingSetPO greetingSet = new GreetingSetPO();
        greetingSet.setName(setName);
        greetingSetDao.create(greetingSet);

        GreetingPO greetingPO = new GreetingPO();
        greetingPO.setGreeting(greeting);
        greetingPO.setGreetingSet(greetingSetDao.findByName(setName));
        Long greetingId = greetingDao.create(greetingPO);

        GreetingPO greetingId2 = greetingDao.findByGreeting(greeting);
        assertEquals(greetingId, greetingId2.getId());
    }

Notice that I’m committing the (empty) greeting set, then pointing the greeting to it and committing the greeting — two create() calls.

Today I talked with the domain guy and found out that the domain code is doing it a little differently:

    /**
     * This test creates a transient greeting set and a transient greeting, points them to each other, and then commits the
     * set-with-the-greeting-in-it. This blows up.
     */
    @Test
    public void testComplexCreate() {
        final String greeting = "Quid est nomen tibi?";
        final String setName = "Latin greetings";
        assertNull(greetingSetDao.findByName(setName));
        assertNull(greetingDao.findByGreeting(greeting));

        GreetingSetPO greetingSetPO = new GreetingSetPO();
        greetingSetPO.setName(setName);

        GreetingPO greetingPO = new GreetingPO();
        greetingPO.setGreeting(greeting);

        // Point the GreetingPO to its GreetingSetPO and vice versa
        greetingPO.setGreetingSet(greetingSetPO);

        Set<GreetingPO> greetings = new HashSet<GreetingPO>();
        greetings.add(greetingPO);
        greetingSetPO.setMembers(greetings);

        greetingSetDao.create(greetingSetPO);

        assertNotNull(greetingSetDao.findByName(setName));
        assertNotNull(greetingDao.findByGreeting(greeting));
    }

Notice that this time, instead of committing the empty greeting set, we create the greeting set and greeting, point them to each other, then commit the set-with-the-greeting-in-it.

This blows up just like the domain code. Yeah!

So now my questions are:

1. Should this single-create() version work?
2. If not, why does it work when we’re using Hibernate local transactions?

Update: I’ve posted my question to the envers forum.

Versioning sets: IllegalArgumentException

We’re experiencing an issue when we try to use envers to version a persistent object that holds a set of other persistent objects, when we’re using Spring’s JTA transaction manager. We’re consistently getting a

org.springframework.transaction.UnexpectedRollbackException: JTA transaction unexpectedly rolled back (maybe due to a timeout); nested exception is bitronix.tm.internal.BitronixRollbackException: transaction was marked as rollback only and has been rolled back
at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1031)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:732)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:701)
at com.ontsys.fw.testutil.transaction.TransactionManager.commit(TransactionManager.java:129)
at com.ontsys.db.inventory.products.dao.ProductSetDAOIntegrationTest.createProduct(ProductSetDAOIntegrationTest.java:409)
at com.ontsys.db.inventory.products.dao.ProductSetDAOIntegrationTest.testRetrieveSetWithSetOfOne(ProductSetDAOIntegrationTest.java:123)

The problem doesn’t happen when we’re using Spring’s HibernateTransactionManager.

The thing that fails succeeds at first

Something that was throwing me for a loop (so to speak) was that the place that is throwing the exception succeeds several times first.  I had a breakpoint in bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent() at the call to synchronization.beforeCompletion(), but I stepped all the way into this and back out, and it worked — the first time.

Counting the times till it fails

I had the idea to keep resuming from that breakpoint to count how many times it succeeded before the exception blew up my test.  I found that it was after it hit the breakpoint in bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent() the eighth time that the beforeCompletion event never returned.  So I set the Hit Count on that breakpoint to 8 (so it wouldn’t break there until the eighth time).

Let’s see that in super slow-motion…

Turns out that it’s the seventh time it hits org.hibernate.event.def.AbstractSaveEventListener.performSave() that the exception occurs, down in a call of org.hibernate.property.BasicPropertyAccessor.BasicSetter.set().  The call stack at the method.invoke() call that will result in the IllegalArgumentException looks like this:

org.hibernate.property.BasicPropertyAccessor$BasicSetter.set(java.lang.Object, java.lang.Object, org.hibernate.engine.SessionFactoryImplementor) line: 66	
org.hibernate.tuple.entity.PojoEntityTuplizer(org.hibernate.tuple.entity.AbstractEntityTuplizer).setIdentifier(java.lang.Object, java.io.Serializable) line: 234	
org.hibernate.persister.entity.SingleTableEntityPersister(org.hibernate.persister.entity.AbstractEntityPersister).setIdentifier(java.lang.Object, java.io.Serializable, org.hibernate.EntityMode) line: 3624	
org.hibernate.event.def.DefaultSaveEventListener(org.hibernate.event.def.AbstractSaveEventListener).performSave(java.lang.Object, java.io.Serializable, org.hibernate.persister.entity.EntityPersister, boolean, java.lang.Object, org.hibernate.event.EventSource, boolean) line: 194	
org.hibernate.event.def.DefaultSaveEventListener(org.hibernate.event.def.AbstractSaveEventListener).saveWithGeneratedId(java.lang.Object, java.lang.String, java.lang.Object, org.hibernate.event.EventSource, boolean) line: 144	
org.hibernate.event.def.DefaultSaveEventListener(org.hibernate.event.def.DefaultSaveOrUpdateEventListener).saveWithGeneratedOrRequestedId(org.hibernate.event.SaveOrUpdateEvent) line: 210	
org.hibernate.event.def.DefaultSaveEventListener.saveWithGeneratedOrRequestedId(org.hibernate.event.SaveOrUpdateEvent) line: 56	
org.hibernate.event.def.DefaultSaveEventListener(org.hibernate.event.def.DefaultSaveOrUpdateEventListener).entityIsTransient(org.hibernate.event.SaveOrUpdateEvent) line: 195	
org.hibernate.event.def.DefaultSaveEventListener.performSaveOrUpdate(org.hibernate.event.SaveOrUpdateEvent) line: 50	
org.hibernate.event.def.DefaultSaveEventListener(org.hibernate.event.def.DefaultSaveOrUpdateEventListener).onSaveOrUpdate(org.hibernate.event.SaveOrUpdateEvent) line: 93	
org.hibernate.impl.SessionImpl.fireSave(org.hibernate.event.SaveOrUpdateEvent) line: 562	
org.hibernate.impl.SessionImpl.save(java.lang.String, java.lang.Object) line: 550	
org.jboss.envers.synchronization.work.PersistentCollectionChangeWorkUnit.perform(org.hibernate.Session, java.lang.Object) line: 67	
org.jboss.envers.synchronization.VersionsSync.executeInSession(org.hibernate.Session) line: 120	
org.jboss.envers.synchronization.VersionsSync.beforeCompletion() line: 135	
bitronix.tm.BitronixTransaction.fireBeforeCompletionEvent() line: 366	
bitronix.tm.BitronixTransaction.commit() line: 142	
bitronix.tm.BitronixTransactionManager.commit() line: 96	
org.springframework.transaction.jta.JtaTransactionManager.doCommit(org.springframework.transaction.support.DefaultTransactionStatus) line: 1028	
org.springframework.transaction.jta.JtaTransactionManager(org.springframework.transaction.support.AbstractPlatformTransactionManager).processCommit(org.springframework.transaction.support.DefaultTransactionStatus) line: 732	
org.springframework.transaction.jta.JtaTransactionManager(org.springframework.transaction.support.AbstractPlatformTransactionManager).commit(org.springframework.transaction.TransactionStatus) line: 701	
com.ontsys.fw.testutil.transaction.TransactionManager.commit() line: 129	
com.ontsys.db.inventory.products.dao.ProductSetDAOIntegrationTest.createProduct(com.ontsys.db.inventory.products.po.ProductPO, java.lang.String) line: 409	
com.ontsys.db.inventory.products.dao.ProductSetDAOIntegrationTest.testRetrieveSetWithSetOfOne() line: 123	
...

A Closer Look at the InvalidArgumentException

What is this IllegalArgumentException that BasicPropertyAccessor.BasicSetter.set() catches when it tries the method.invoke()?  The contained message is:

object is not an instance of declaring class

BasicPropertyAccessor.BasicSetter.set() then logs these messages:

IllegalArgumentException in class: com.ontsys.fw.datatypes.BaseTO, setter method of property: key
expected type: java.lang.String, actual value: java.lang.String

(Hmm, expected a java.lang.String but got a java.lang.String, huh?) …and then throwing an exception:

org.hibernate.PropertyAccessException: IllegalArgumentException occurred while calling setter of com.ontsys.fw.datatypes.BaseTO.key

Going back to the IllegalArgumentException’s message, though: why would our object not be an instance of the declaring class?

That, my friends, will have to wait until next time.

The final answer

This post is part 8 in a 9-part series on Envers, Spring, and JTA. The next post is Blowing up in test mode, and the previous post is An answer.

---

The story thus far:

The envers beforeCompletion() hook was not running when I switched from using Spring’s HibernateTransactionManager to using its JtaTransactionManager.  I had done some digging on my own, then made a long post to the Spring Data Access forum (after an initial post to the envers forum).

The long post apparently scared everybody off ;) , so I wrote a much shorter, more focused post.

A reply to the shorter post pointed me to the SessionFactoryUtils javadoc, where I read:

Note that for non-Spring JTA transactions, a JTA TransactionManagerLookup has to be specified in the Hibernate configuration.

On the trail of how to specify a TransactionManagerLookup, I found the hibernate.transaction.manager_lookup_class setting in the Using JTA section of the Hibernate Reference Guide — but unbeknownst to me, another setting was needed…

Final Answer

A Hibernate Users forum post titled How can i use JTA with Hibernate? points to the Transaction demarcation with JTA section of the Sessions and transactions Wiki page, where we see:

• set hibernate.transaction.manager_lookup_class to a lookup strategy for your JEE container
• set hibernate.transaction.factory_class to org.hibernate.transaction.JTATransactionFactory

So, adding these two lines to my Hibernate spring beans file (lines 6 and 7 below) fixed the issue:

<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
		...
<property name="hibernateProperties">
<props>
				...
<prop key="hibernate.transaction.manager_lookup_class">org.hibernate.transaction.JBossTransactionManagerLookup</prop>
<prop key="hibernate.transaction.factory_class">org.hibernate.transaction.JTATransactionFactory</prop>
			</props>
		</property>
		...
    </bean>

NOW the envers beforeCompletion() hook gets called when using the JTA transaction manager.

Whew!

beforeCompletion, I need to figure this out

This post is part 6 in a 9-part series on Envers, Spring, and JTA. The next post is An answer, and the previous post is The versioning isn’t happening, part 4a: phone a friend.

---

I’m just getting back to the envers-JTA-hooks-not-getting-called thing — the following is from work I did last Wednesday —

---

A post to the Spring Data Access forum had this interesting line:

DEBUG [org.springframework.transaction.jta.JtaTransactionManager] Triggering beforeCompletion synchronization

Hey!  Just when I was beginning to worry that Spring’s JtaTransactionManager had never heard of beforeCompletion and didn’t intend to call that callback.  So… where is that line of code, and who calls it?

Where It Is, and Who Calls It

Back at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(TransactionStatus), this calls its own internal processCommit() method, which — why did we not notice this before? — does these things (among others):

prepareForCommit(status);
triggerBeforeCommit(status);
triggerBeforeCompletion(status);

TriggerBeforeCompletion() ?!  Firing up the ol’ debugger, I do make it in there.  So it *is* trying to run the beforeCompletion Synchronizations, methinks.  Perhaps they aren’t being registered?

triggerBeforeCompletion() calls TransactionSynchronizationUtils.triggerBeforeCompletion(), which calls org.springframework.transaction.support.TransactionSynchronizationManager.getSynchronizations().  (The TransactionSynchronizationManager is also the class that has a registerSynchronization(TransactionSynchronization) method — but instead of taking a javax.transaction.Synchronization, it takes a org.springframework.transaction.support.TransactionSynchronization.)

The only TransactionSynchronization that’s in there currently is a org.springframework.orm.hibernate3.SpringSessionSynchronization.

Envers’ org.jboss.envers.synchronization.VersionsSyncManager.get(EventSource session) calls session.getTransaction().registerSynchronization().  The getTransaction() call returns an org.hibernate.transaction.JDBCTransaction.

Next step: Can we get at that JDBCTransaction from JtaTransactionManager’s doCommit()?  Or alternatively, can the thing passed as an EventSource to VersionsSyncManager.get() be something that wraps a JDBCTransaction and also registers with the Spring TransactionSynchronizationManager?

The versioning isn’t happening, part 4a: phone a friend

This post is part 5 in a 9-part series on Envers, Spring, and JTA. The next post is beforeCompletion, I need to figure this out, and the previous post is The versioning isn’t happening, part 4: Registering with the wrong transaction?

---

The time had come to ask my questions at the Spring Data Access forum.  Following is a copy of that forum post (Whew, does it take work to try to ask a question well!) :

Sychronization hook not called when using JTA txmgr

---

Summary
We’re using Spring 2.5.5 on JBoss 4.2.2.GA, along with JBoss envers version 1.1.0.GA. (Envers uses Hibernate’s onPostInsert() hook to register a javax.transaction.Synchronization callback that’s called during transaction commit, to write audit records about records that were created during that transaction.)When we use Spring’s HibernateTransactionManager and write a record, the registered envers javax.transaction.Synchronization.beforeCompletion () event handler fires as expected, but when we use Spring’s jta-transaction-manager, the registered envers beforeCompletion() event handler does not fire. In this post, after sketching our configuration, I discuss what I see working the same and different between the HibernateTransactionManager and jta-transaction-manager scenarios, and close by pointing out where I think the problem might be in Spring.

Our Configuration
We’ve configured the Hibernate sessionFactory bean to hook it up to envers’ VersionsEventListener (which implements org.hibernate.event.PostInsertEventListener):

<bean id="versionsEventListener" class="org.jboss.envers.event.VersionsEventListener" />
	<bean id="sessionFactory" class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
		...
<property name="eventListeners">
			<map>
				<entry key="post-insert">
					<ref local="versionsEventListener" />
				</entry>
				...
			</map>
		</property>
		...
	</bean>

With this configuration, every time a new row is inserted into the main table,

1. org.jboss.envers.event.VersionsEventListener.onPos tInsert(PostInsertEvent event) is called
2. onPostInsert() passes event.getSession() to org.jboss.envers.synchronization.VersionsSyncManag er.get(EventSource)
3. VersionsSyncManager.get() then calls getTransaction() (which returns a JDBCTransaction) on the EventSource
4. Finally, VersionsSyncManager.get() calls registerSynchronization() on this transaction to register a javax.transaction.Synchronization object whose beforeCompletion() method should be called during the transaction commit.

It is the code in this beforeCompletion() method that does the writing of the versioning records.

HibernateTransactionManager vs. JtaTransactionManager
When I set up my .war project’s Spring beans to use the Hibernate transaction manager:

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

then the VersionsEventListener.onPostInsert() call happens as I have descibed, and later the registered beforeCompletion() hook is called and envers writes my audit records to the database. But when I remove the above bean and use the JTA transaction manager:

	<tx:jta-transaction-manager />

the VersionsEventListener.onPostInsert() call still happens and I do see registerSynchronization() being called; but this time the envers beforeCompletion() hook never gets called (and thus the audit records are not written to the database).

Registering with a JDBCTransaction, Committing a UserTransaction?
That’s the main symptom. I’ll now speculate on the cause… : )

When I’m using the HibernateTransactionManager, I notice that its doCommit() method makes this call:

txObject.getSessionHolder().getTransaction().commit();

Here, getTransaction() returns an org.hibernate.transaction.JDBCTransaction (the same one that envers called registerSynchronization() on earlier). As part of this commit(), the JDBCTransaction calls its notifyLocalSynchsBeforeTransactionCompletion() method, which calls the javax.transaction.Synchonization.beforeCompletion( ) registered by envers. So I see how the hook works on the HibernateTransactionManager side. On the JtaTransactionManager side though, org.springframework.transaction.jta.JtaTransaction Manager.doCommit() makes this call:

txObject.getUserTransaction().commit();

Here, getUserTransaction() returns the javax.transaction.UserTransaction, and then we call commit() on that. This commit() call does not result in the envers javax.transaction.Synchronization.beforeCompletion () being called. Something I notice here is that envers’ onPostInsert() method caused registerSynchronization() to be called on a JDBCTransaction object, not the UserTransaction object. This JDBCTransaction object appears to be unused for the purposes of committing.

Why I think it might be an issue in Spring
Envers’ VersionsEventListener.onPostInsert(PostInsertEvent event) method receives an org.hibernate.event.PostInsertEvent, and it is from this event that envers eventually calls (effectively):

event.getSession().getTransaction().registerSynchronization()

Envers is registering its Synchronization object with the transaction given to it by the PostInsertEvent — I don’t immediately see how it could do any differently (though I’m far from an expert at these things)…Meanwhile, I don’t see where Spring is informing the UserTransaction about these registered synchronizations, and I don’t see Spring taking care of them itself either. It seems to my uneducated eyes that Spring should be doing one or the other of these, so that the registered callbacks aren’t just lost. Is there something I’m missing?

Thank you for your patience with this long post!
-Daniel-

The versioning isn’t happening, part 4: Registering with the wrong transaction?

This post is part 4 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 4a: phone a friend, and the previous post is The versioning isn’t happening, part 3: it’s in UserTransaction?

---

Looky here:

While looking at the javadoc for javax.transaction.Synchronization earlier, I had noticed this:

Using the registerSynchronization method, the application server registers a Synchronization object for the transaction currently associated with the target Transaction object.

Now, the only registerSynchronization() method I see is javax.transaction.Transaction’s registerSynchronization() method, and the one place that registerSynchronization() is called from the envers code is in org.jboss.envers.synchronization.VersionsSyncManager.get(EventSource).

Here’s an interesting thing: when I set a breakpoint on VersionsSyncManager.get(EventSource) and start stepping through the code, the first thing it does (line 47) is do a session.getTransaction().  I expected that underneath, this would be our javax.transaction.UserTransaction (since we’re running in JTA mode), but instead when we call transaction.registerSynchronization() I see that we have a org.hibernate.transaction.JDBCTransaction.

Wrong Number?

So to step back a moment, what we have here is a Synchronization being registered with a JDBCTransaction, when the actual work will be done by a javax.transaction.UserTransaction.  It seems plausible that when the UserTransaction goes to commit, it won’t run these registered synchronizations (since it seems it wouldn’tknow about them).

Why does EventSource.getTransaction() return a JDBCTransaction instead of the UserTransaction?

EventSource extends org.hibernate.Session, and the javadoc for org.hibernate.Session.getTransaction() has this interesting tidbit:

The class of the returned Transaction object is determined by the property hibernate.transaction_factory.

The closest to this that I see in the AnnotationConfig is:

hibernate.transaction.factory_class=org.springframework.orm.hibernate3.SpringTransactionFactory

So what does SpringTransactionFactory do?

Hmm: org.springframework.orm.hibernate3.SpringTransactionFactory.createTransaction(JDBCContext, Context) returns a new JDBCTransaction, even if we’re in JTA mode.  That is the transaction that is returned (I think) by org.hibernate.Session.getTransaction().  Is that a bug?  Or alternatively, is the problem that Spring’s JtaTransactionManager calls commit() on the UserTransaction directly, without taking into account the synchronizations registered on the companion JDBCTransaction object?  It seems that one way or another, someone should be taking responsibility for getting those registered callbacks called!

(Next: Time to ask for help!)

The versioning isn’t happening, part 3: it’s in UserTransaction?

This post is part 3 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 4: Registering with the wrong transaction?, and the previous post is The versioning isn’t happening, part 2: beforeCompletion.

---

We’re trying to figure out why the envers versioning records are not created when our project uses a JTA transaction manager — it creates the versioning records just fine when we’re using local Hibernate transactions.

In part 2, we discovered that while org.jboss.envers.synchronization.VersionsSync.beforeCompletion() is called when we’re running in Hibernate mode, it is not getting called when we’re in JTA mode, even though onPostInsert is being called just like in Hibernate mode.

To dig farther toward the root of this, let’s see where the call to beforeCompletion() comes from when we’re in Hibernate mode…

1. Hibernate mode

I deployed the hibernate-mode version again and sent a message with a method-entry breakpoint on the VersionsSync beforeCompletion() call.  This time, I set breakpoints on the lines farther up the call stack — the last six entries in the chain of calls yielding the call to beforeCompletion().  My list of breakpoints now looks like this:

AbstractPlatformTransactionManager [line: 678] - commit(TransactionStatus)
AbstractPlatformTransactionManager [line: 709] - processCommit(DefaultTransactionStatus)
HibernateTransactionManager [line: 655] - doCommit(DefaultTransactionStatus)
JDBCTransaction [line: 109] - commit()
JDBCTransaction [line: 228] - notifyLocalSynchsBeforeTransactionCompletion()
TransactionAspectSupport [line: 321] - commitTransactionAfterReturning(TransactionInfo)
VersionsSync [entry] - beforeCompletion()

Now we’ll run it in jta mode and see if we get to any of these breakpoints.

2. JTA mode

We do break at TransactionInterceptor(TransactionAspectSupport).commitTransactionAfterReturning(TransactionAspectSupport$TransactionInfo) line: 321 (but… ohhhh, I stepped too slowly and the transaction timed out, yielding a stack trace!  Trying again…)

We’re at JtaTransactionManager(AbstractPlatformTransactionManager).commit(TransactionStatus) line: 678 and then JtaTransactionManager.doCommit(DefaultTransactionStatus)… so far this is just like Hibernate mode.  org.springframework.transaction.jta.JtaTransactionManager.doCommit(DefaultTransactionStatus) mainly just does txObjext.getUserTransaction().commit() (line 1028) — this is still analogous to what we see on the Hibernate-mode side (there, it’s org.springframework.orm.hibernate3.HibernateTransactionManager.doCommit(DefaultTransactionStatus), which mainly just calls txObject.getSessionHolder().getTransaction().commit() (line 655).)

2.1. A closer look at the Hibernate-mode commit() call

Let’s look more closely at this call:

txObject.getSessionHolder().getTransaction().commit()

The getTransaction() call returns a org.hibernate.transaction.JDBCTransaction object, which we then call commit() on.  And it is this commit() method that calls org.hibernate.transaction.JDBCTransaction.notifyLocalSynchsBeforeTransactionCompletion(), which calls the beforeCompletion() method.

2.2. The Difference on the JTA Side

The call mentioned in step 1.2.1. is what causes beforeCompletion() to be called (which creates the envers versioning records) when we’re in Hibernate mode.  The analogous call when we’re in JTA mode is:

txObjext.getUserTransaction().commit();

(Called by org.springframework.transaction.jta.JtaTransactionManager.doCommit(DefaultTransactionStatus) on line 1028.)

Now, getUserTransaction() returns the javax.transaction.UserTransaction from JBoss; and then we call commit() on that.  Somewhere inside that commit() call, javax.transaction.Synchronization.beforeCompletion()* is not being called.

*VersionsSync implements javax.transaction.Synchronization; any beforeCompletion() call in an app server’s UserTransaction would reference the javax.transaction.Synchronization interface rather than org.jboss.envers.synchronization.VersionsSync, I’m sure!

In our next installment, let’s look into why UserTransaction is not calling beforeCompletion().

The versioning isn’t happening, part 2: beforeCompletion

This post is part 2 in a 9-part series on Envers, Spring, and JTA. The next post is The versioning isn’t happening, part 3: it’s in UserTransaction?, and the previous post is The versioning isn’t happening, part 1: wanderings.

---

We’re trying to figure out why the envers versioning records are not created when our project uses a JTA transaction manager — it creates the versioning records just fine when we’re using local Hibernate transactions.

Our approach last time was to see what differences there might be in the Hibernate configuration.  I ended up that post with

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.

-1. The Other 47 Fields

After I stopped writing last time, I did go on to capture the 47 AnnotationConfiguration fields’ values when running in Hibernate mode and when running in JTA mode, and… they were the same!  (Keith suspected they would be.)

0. No Other Apparent Magic During JBoss Startup

Still running in Hibernate mode, I followed the control flow after the creation of the Hibernate SessionFactory bean, but I didn’t see anything interesting-looking.  It’s hard to let the idea go that something’s different at startup time, but I think next I need to take a closer look at what happens during a save to the database.

1. A list of work to do later

Let’s see where the envers onPostInsert() hook gets called from, in hibernate mode (i.e., where things are working correctly). Here’s the call stack:

Daemon Thread [http-127.0.0.1-8080-1] (Suspended (entry into method onPostInsert in VersionsEventListener))
VersionsEventListener.onPostInsert(PostInsertEvent) line: 88
EntityInsertAction.postInsert() line: 131
EntityInsertAction.execute() line: 110
ActionQueue.execute(Executable) line: 279
ActionQueue.executeActions(List) line: 263
ActionQueue.executeActions() line: 167
DefaultFlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 298
DefaultFlushEventListener.onFlush(FlushEvent) line: 27
SessionImpl.flush() line: 1000
GreetingDAO(GenericDAO<PO,PK>).create(PO) line: 66
GreetingDBSvcImpl.saveGreeting(GreetingPTO) line: 25
GreetingSvcImpl.saveGreeting(GreetingDTO) line: 21
HelloWorldSvcImpl.writeGreetingToDatabase(Greeting) line: 24
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39

1.1. It’s all the same in JTA mode

I set breakpoints at most of these places.  Let’s try it in jta mode:

• We get to the session.flush() in GreetingDAO(GenericDAO<PO,PK>).create(PO) line: 66
• We get to DefaultFlushEventListener.onFlush(FlushEvent) line: 27
• We get to DefaultFlushEventListener(AbstractFlushingEventListener).performExecutions(EventSource) line: 298
• We get to ActionQueue.executeActions() line: 167 with 1 element in our insertions ArrayList to do, just like in hibernate mode
• We get to EntityInsertAction.execute() line: 110
• We get into EntityInsertAction.postInsert(), with a org.jboss.envers.event.VersionsEventListener and a org.hibernate.search.event.FullTextIndexEventListenerin the postInsertEventListener[] array
• We even get into VersionsEventListener.onPostInsert(PostInsertEvent)!

So why doesn’t the versioning happen?

It turns out that VersionsEventListener.onPostInsert() isn’t where the real work is done.

1.2. What VersionsEventListener.onPostInsert() is responsible for

Summary:

VersionsEventListener.onPostInsert() adds a VersionsWorkUnit to a list, to be picked up and performed later.  It doesn’t actually do the work.

Details:

org.jboss.envers.event.VersionsEventListener.onPostInsert(PostInsertEvent) does is to add the org.jboss.envers.synchronization.work.VersionsWorkUnit to the org.jboss.envers.synchronization.VersionsSync.workUnits linked list (VersionsSync is the class that implements javax.transaction.Synchronization).

3. Who picks up the work unit?

Who is responsible for picking up the work unit, then?  I notice that the javax.transaction.Synchronization specifies two methods: beforeCompletion() and afterCompletion(int).  Let’s see if anyone calls beforeCompletion() when we’re in Hibernate mode… setting breakpoints on these two methods and re-running my hibernate mode test, we break at beforeCompletion() with this call stack:

Daemon Thread [http-127.0.0.1-8080-1] (Suspended (entry into method beforeCompletion in VersionsSync))
VersionsSync.beforeCompletion() line: 125
JDBCTransaction.notifyLocalSynchsBeforeTransactionCompletion() line: 228
JDBCTransaction.commit() line: 109
HibernateTransactionManager.doCommit(DefaultTransactionStatus) line: 655
HibernateTransactionManager(AbstractPlatformTransactionManager).processCommit(DefaultTransactionStatus) line: 709
HibernateTransactionManager(AbstractPlatformTransactionManager).commit(TransactionStatus) line: 678
TransactionInterceptor(TransactionAspectSupport).commitTransactionAfterReturning(TransactionAspectSupport$TransactionInfo)line: 321
TransactionInterceptor.invoke(MethodInvocation) line: 116
ReflectiveMethodInvocation.proceed() line: 171
ExposeInvocationInterceptor.invoke(MethodInvocation) line: 89
ReflectiveMethodInvocation.proceed() line: 171
JdkDynamicAopProxy.invoke(Object, Method, Object[]) line: 204
$Proxy68.writeGreetingToDatabase(Greeting) line: not available
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25
Method.invoke(Object, Object...) line: 585
JAXWSMethodInvoker(AbstractInvoker).performInvocation(Exchange, Object, Method, Object[]) line: 136
JAXWSMethodInvoker(AbstractInvoker).invoke(Exchange, Object, Method, List<Object>) line: 82
JAXWSMethodInvoker.invoke(Exchange, Object, Method, List<Object>) line: 97
JAXWSMethodInvoker(AbstractInvoker).invoke(Exchange, Object) line: 68
ServiceInvokerInterceptor$1.run() line: 56
SynchronousExecutor.execute(Runnable) line: 37
ServiceInvokerInterceptor.handleMessage(Message) line: 92
PhaseInterceptorChain.doIntercept(Message) line: 221
ChainInitiationObserver.onMessage(Message) line: 78
ServletDestination.invoke(ServletContext, HttpServletRequest, HttpServletResponse) line: 92
ServletController.invokeDestination(HttpServletRequest, HttpServletResponse, ServletDestination) line: 279
ServletController.invoke(HttpServletRequest, HttpServletResponse) line: 161
CXFServlet(AbstractCXFServlet).invoke(HttpServletRequest, HttpServletResponse) line: 174
CXFServlet(AbstractCXFServlet).doPost(HttpServletRequest, HttpServletResponse) line: 152
CXFServlet(HttpServlet).service(HttpServletRequest, HttpServletResponse) line: 710
CXFServlet(HttpServlet).service(ServletRequest, ServletResponse) line: 803
ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) line: 290
ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) line: 206
ReplyHeaderFilter.doFilter(ServletRequest, ServletResponse, FilterChain) line: 96
ApplicationFilterChain.internalDoFilter(ServletRequest, ServletResponse) line: 235
ApplicationFilterChain.doFilter(ServletRequest, ServletResponse) line: 206
StandardWrapperValve.invoke(Request, Response) line: 230
StandardContextValve.invoke(Request, Response) line: 175
SecurityAssociationValve.invoke(Request, Response) line: 179
JaccContextValve.invoke(Request, Response) line: 84
StandardHostValve.invoke(Request, Response) line: 127
ErrorReportValve.invoke(Request, Response) line: 102
CachedConnectionValve.invoke(Request, Response) line: 157
StandardEngineValve.invoke(Request, Response) line: 109
CoyoteAdapter.service(Request, Response) line: 262
Http11Processor.process(Socket) line: 844
Http11Protocol$Http11ConnectionHandler.process(Socket) line: 583
JIoEndpoint$Worker.run() line: 446
Thread.run() line: 595

So VersionsSync.beforeCompletion() does indeed get called when we’re in Hibernate mode.

3.1. Sidenote: The Point Where the Records Appear in the Tables

After some more lines of code, we get to org.hibernate.transaction.JDBCTransaction.commitAndResetAutoCommit(), which does a  jdbcContext.connection().commit().  Before this line is executed, neither the main record nor the versioning record appear in the table; after that line, the records do appear.

4. JTA mode: no beforeCompletion call made

Next we’ll re-run the test we did in step 3 with the jta version deployed and with all the same breakpoints, to see if org.jboss.envers.synchronization.VersionsSync.beforeCompletion() gets called…

It doesn’t.

Tune in next time for an exploration of why VersionsSync.beforeCompletion() isn’t getting called in JTA mode!

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…!)