The versioning isn’t happening, part 2: beforeCompletion
Posted by danielmeyer on December 4, 2008
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!
EDH said
Hi,
I’ve read through this excellent post. It confirms that getting txns to work with Spring and Hibernate isn’t that straightforward.
Perhaps you can help me out ?
I’ve got a Spring 2.5.6, JUnit4.4, Hibernate 3.3.2 setup.
I’ve got a JUnit testmethod annotated with @Test and with @NotTransactional.
The testmethod’s class is injected with a GebruikerServiceAccess gebruikerServiceAcces bean.
The testmethod calls getGebruikerServiceAccess().createGebruiker().
That method’s class is injected with GebruikerService gebruikerService.
The GebruikerService.createGebruiker() calls its ingejected dao and then calls getPersoonService().createPersoon().
All methods on GebruikerService are declared (Spring xml file) as txn “REQUIRED”.
All methods on PersoonService are declared (Spring xml file) as txn “REQUIRES_NEW”.
I’m using:
...
...
...
...
</code
If I'm not mistaken I can see in the debug output that a new txn and session is created when calling the GebruikerServcie.createGebruiker():
2010-02-02 15:15:13,806 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Creating new transaction with name [be.vlaanderen.techstack.basis.gebruiker.service.GebruikerService.createGebruiker]: PROPAGATION_REQUIRED,ISOLATION_READ_COMMITTED,-be.vlaanderen.techstack.basis.exception.BusinessException,+org.springframework.orm.ObjectRetrievalFailureException
2010-02-02 15:15:13,856 DEBUG [org.hibernate.impl.SessionImpl] - opened session at timestamp: 5181931986149376
2010-02-02 15:15:13,856 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Opened new Session [org.hibernate.impl.SessionImpl@1de041e] for Hibernate transaction
2010-02-02 15:15:13,856 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@1de041e]
2010-02-02 15:15:13,886 DEBUG [org.hibernate.jdbc.ConnectionManager] - opening JDBC connection
2010-02-02 15:15:13,886 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver] to 2
2010-02-02 15:15:13,906 DEBUG [org.hibernate.transaction.JDBCTransaction] - begin
2010-02-02 15:15:13,906 DEBUG [org.hibernate.transaction.JDBCTransaction] - current autocommit status: true
2010-02-02 15:15:13,906 DEBUG [org.hibernate.transaction.JDBCTransaction] - disabling autocommit
2010-02-02 15:15:13,906 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Exposing Hibernate transaction as JDBC transaction [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver]
2010-02-02 15:15:13,906 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Found thread-bound Session [org.hibernate.impl.SessionImpl@1de041e] for Hibernate transaction
2010-02-02 15:15:13,906 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Participating in existing transaction
2010-02-02 15:15:13,916 DEBUG [org.springframework.orm.hibernate3.HibernateTemplate] - Found thread-bound Session for HibernateTemplate
2010-02-02 15:15:13,916 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - generated identifier: 3bf81452-cf8a-4eb8-af1a-84a09bbb25dd, using strategy: org.hibernate.id.Assigned
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTemplate] - Not closing pre-bound Hibernate Session after HibernateTemplate
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Found thread-bound Session [org.hibernate.impl.SessionImpl@1de041e] for Hibernate transaction
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Participating in existing transaction
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Found thread-bound Session [org.hibernate.impl.SessionImpl@1de041e] for Hibernate transaction
I can also see that that txn is getting suspended and another txn and session is being created when calling PersoonService.createPersoon(), from GebruikerService.createGebruiker().
And I can also see that this txn is getting rolledback due to the exception I expected to be thrown (DataIntegrityViolationException):
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Suspending current transaction, creating new transaction with name [be.vlaanderen.ov.led.persoon.service.PersoonService.createPersoon]
2010-02-02 15:15:13,946 DEBUG [org.hibernate.impl.SessionImpl] - opened session at timestamp: 5181931986722816
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Opened new Session [org.hibernate.impl.SessionImpl@487c5f] for Hibernate transaction
2010-02-02 15:15:13,946 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@487c5f]
2010-02-02 15:15:13,946 DEBUG [org.hibernate.jdbc.ConnectionManager] - opening JDBC connection
org.springframework.dao.DataIntegrityViolationException: not-null property references a null or transient value: be.vlaanderen.ov.led.persoon.domain.PersoonImpl.inszNummer; nested exception is org.hibernate.PropertyValueException: not-null property references a null or transient value: be.vlaanderen.ov.led.persoon.domain.PersoonImpl.inszNummer
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:645)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:412)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:424)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:748)2010-02-02 15:15:14,077 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Changing isolation level of JDBC Connection [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver] to 2
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - begin
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - current autocommit status: true
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - disabling autocommit
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Exposing Hibernate transaction as JDBC transaction [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver]
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTemplate] - Found thread-bound Session for HibernateTemplate
2010-02-02 15:15:14,077 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - generated identifier: e0b6c652-5995-47b7-b1bd-01827d1ef0f0, using strategy: org.hibernate.id.Assigned
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTemplate] - Not closing pre-bound Hibernate Session after HibernateTemplate
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Initiating transaction rollback
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Rolling back Hibernate transaction on Session [org.hibernate.impl.SessionImpl@487c5f]
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - rollback
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - re-enabling autocommit
2010-02-02 15:15:14,077 DEBUG [org.hibernate.transaction.JDBCTransaction] - rolled back JDBC Connection
2010-02-02 15:15:14,077 DEBUG [org.hibernate.jdbc.ConnectionManager] - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2010-02-02 15:15:14,077 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Resetting isolation level of JDBC Connection [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver] to 2
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Closing Hibernate Session [org.hibernate.impl.SessionImpl@487c5f] after transaction
2010-02-02 15:15:14,077 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] - Closing Hibernate Session
2010-02-02 15:15:14,077 DEBUG [org.hibernate.jdbc.ConnectionManager] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2010-02-02 15:15:14,077 DEBUG [org.hibernate.jdbc.ConnectionManager] - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
I then see the first txn resuming, something I also expected:
2010-02-02 15:15:14,087 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Resuming suspended transaction
2010-02-02 15:15:14,087 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Participating transaction failed - marking existing transaction as rollback-only
2010-02-02 15:15:14,087 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Setting Hibernate transaction on Session [org.hibernate.impl.SessionImpl@1de041e] rollback-only
at be.vlaanderen.techstack.basis.dao.GenericDaoHibernateImpl.saveOrUpdate(GenericDaoHibernateImpl.java:92)
...
However what I don't understand is why this first txn is also marked for rollback ?
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Global transaction is marked as rollback-only but transactional code requested commit
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Participating transaction failed - marking existing transaction as rollback-only
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Setting Hibernate transaction on Session [org.hibernate.impl.SessionImpl@1de041e] rollback-only
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Global transaction is marked as rollback-only but transactional code requested commit
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Initiating transaction rollback
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Rolling back Hibernate transaction on Session [org.hibernate.impl.SessionImpl@1de041e]
2010-02-02 15:15:14,137 DEBUG [org.hibernate.transaction.JDBCTransaction] - rollback
2010-02-02 15:15:14,137 DEBUG [org.hibernate.transaction.JDBCTransaction] - re-enabling autocommit
2010-02-02 15:15:14,137 DEBUG [org.hibernate.transaction.JDBCTransaction] - rolled back JDBC Connection
2010-02-02 15:15:14,137 DEBUG [org.hibernate.jdbc.ConnectionManager] - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2010-02-02 15:15:14,137 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] - Resetting isolation level of JDBC Connection [jdbc:oracle:thin:@VM-IDE-01:1521:XE, UserName=LED_D, Oracle JDBC driver] to 2
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.HibernateTransactionManager] - Closing Hibernate Session [org.hibernate.impl.SessionImpl@1de041e] after transaction
2010-02-02 15:15:14,137 DEBUG [org.springframework.orm.hibernate3.SessionFactoryUtils] - Closing Hibernate Session
2010-02-02 15:15:14,137 DEBUG [org.hibernate.jdbc.ConnectionManager] - releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2010-02-02 15:15:14,137 DEBUG [org.hibernate.jdbc.ConnectionManager] - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
danielmeyer said
Dear EDH,
Thanks for posting!
Another time that I experienced an issue like this, what was happening was an exception was being thrown deep in the guts of the commit process, and the details of this precipitating exception were masked by the generic “rolling back” exception (I don’t remember if it was Spring or Hibernate or another library that did the detail-swallowing).
How I eventually found the precipitating cause was by stepping through the commit in the debugger. To support such debugging, I created a little minimal test class to fill out the objects and commit them via Hibernate. You might need to set your database commit timeout higher – I remember that if I thought too long while stepping through, the commit timer would time out and I’d get a rollback even earlier.
Hope this helps…