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.

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!