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!

Advertisements

, , ,

  1. #1 by EDH on February 2, 2010 - 10:47 am

    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!

  2. #2 by danielmeyer on February 8, 2010 - 10:15 am

    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…

  1. Sagas | Our Craft

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s