Cryptic JTS5031 and JTS5068 errors on Sun Application Server 8.1 and 8.2

We encountered the following exceptions when testing our EJB 2.1 + Spring + Hibernate + Osworkflow (also using Hibernate) application.

When running on Sun Application Server 8.1 EE, the stack trace is listed below:

[#2007-10-25T10:50:34.347+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: enlistComponentResources#]
[#2007-10-25T10:50:34.400+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;--Created new J2EETransaction, txId = 25#]
[#2007-10-25T10:50:34.400+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: enlistComponentResources#]
[#2007-10-25T10:50:34.401+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;
In J2EETransactionManagerOpt.enlistResource, h=5 h.xares=com.sun.gjc.spi.XAResourceImpl@c21e52 h.alloc=com.sun.enterprise.resource.ConnectorAllocator@54d24d tx=J2EETransaction: txId=25 nonXAResource=null jtsTx=null localTxStatus=0 syncs=[]#]
[#2007-10-25T10:50:34.401+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: begin#]
[#2007-10-25T10:50:34.402+1000FINEsun-appserver-ee8.1_02javax.enterprise.system.core.transaction_ThreadID=13;Control object :com.sun.jts.CosTransactions.ControlImpl@162aeda corresponding to this transaction has been createdGTID is : 19000000BBF79CD4616476627661707030312C5033373030#]
[#2007-10-25T10:50:34.402+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: enlistResource#]
[#2007-10-25T10:50:34.402+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;--In J2EETransaction.enlistResource, jtsTx=com.sun.jts.jta.TransactionImpl@ffe966e9 nonXAResource=null#]
[#2007-10-25T10:50:34.404+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;--In J2EETransaction.registerSynchronization, jtsTx=com.sun.jts.jta.TransactionImpl@ffe966e9 nonXAResource=null#]
[#2007-10-25T10:50:34.405+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;--In J2EETransaction.registerSynchronization, jtsTx=com.sun.jts.jta.TransactionImpl@ffe966e9 nonXAResource=null#]
[#2007-10-25T10:50:34.406+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: delistResource#]
[#2007-10-25T10:50:34.406+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13; ejbDestroyed: AccountProcessServiceBean; id: [B@7219a#]
[#2007-10-25T10:50:34.406+1000FINEsun-appserver-ee8.1_02javax.enterprise.resource.jta_ThreadID=13;TM: rollback#]
[#2007-10-25T10:50:34.406+1000FINEsun-appserver-ee8.1_02javax.enterprise.system.core.transaction_ThreadID=13;Within TopCoordinator.rollback() :GTID is : 19000000BBF79CD4616476627661707030312C5033373030#]
[#2007-10-25T10:50:34.409+1000SEVEREsun-appserver-ee8.1_02javax.enterprise.system.core.transaction_ThreadID=13;JTS5031: Exception [org.omg.CORBA.INTERNAL: vmcid: 0x0 minor code: 0 completed: Maybe] on Resource [rollback] operation.#]
[#2007-10-25T10:50:34.410+1000FINEsun-appserver-ee8.1_02javax.enterprise.system.container.ejb_ThreadID=13;context with empty container in ContainerSynchronization.afterCompletion#]
[#2007-10-25T10:50:34.410+1000FINEsun-appserver-ee8.1_02javax.enterprise.system.core.transaction_ThreadID=13;Within TopCoordinator.rollback() :GTID is : 19000000BBF79CD4616476627661707030312C5033373030#]
[#2007-10-25T10:50:34.411+1000FINEsun-appserver-ee8.1_02javax.enterprise.system.container.ejb_ThreadID=13;EJB5092:Exception occurred in postInvokeTx : [{0}]
javax.transaction.SystemException: org.omg.CORBA.INTERNAL: JTS5031: Exception [org.omg.CORBA.INTERNAL: vmcid: 0x0 minor code: 0 completed: Maybe] on Resource [rollback] operation. vmcid: 0x0 minor code: 0 completed: No
        at com.sun.jts.jta.TransactionManagerImpl.rollback(TransactionManagerImpl.java:295)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.rollback(J2EETransactionManagerImpl.java:1054)
        at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.rollback(J2EETransactionManagerOpt.java:391)
        at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:2711)
        at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:2521)
        at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:819)
        at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:137)
        at $Proxy22.processUser(Unknown Source)
        at au.net.ozgwei.services.userprocess.UserProcessServiceDelegate.processUser(UserProcessServiceDelegate.java:96)
...
[#2007-10-25T10:50:34.414+1000INFOsun-appserver-ee8.1_02javax.enterprise.system.container.ejb_ThreadID=13;EJB5018: An exception was thrown during an ejb invocation on [UserProcessServiceBean]#]

When running on Sun Application Server 8.2 PE, the stack trace is listed below:

[#2007-10-25T17:52:04.079+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;454609 [httpWorkerThread-2189-4] INFO  org.hibernate.impl.SessionFactoryObjectFactory  - Not binding factory to JNDI, no JNDI name configured
#]
[#2007-10-25T17:52:04.079+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;454609 [httpWorkerThread-2189-4] INFO  org.hibernate.util.NamingHelper  - JNDI InitialContext properties:{}
#]
[#2007-10-25T17:52:04.079+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;454609 [httpWorkerThread-2189-4] INFO  org.springframework.context.support.ClassPathXmlApplicationContext  - Bean 'siteManagerSessionFactory' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
#]
[#2007-10-25T17:52:04.110+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;454640 [httpWorkerThread-2189-4] INFO  org.springframework.context.support.ClassPathXmlApplicationContext  - Bean 'org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor' is not eligible for getting processed by all BeanPostProcessors (for example: not eligible for auto-proxying)
#]
[#2007-10-25T17:52:04.110+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;454640 [httpWorkerThread-2189-4] INFO  org.springframework.beans.factory.support.DefaultListableBeanFactory  - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@1956ba5: defining beans [siteManager,siteRepository,siteAssembler,org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor,dataSource,transactionManager,siteManagerSessionFactory,eventLogService]; root of factory hierarchy
#]
[#2007-10-25T17:52:05.207+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;455737 [httpWorkerThread-2189-4] INFO  org.springframework.transaction.jta.JtaTransactionManager  - Using JTA UserTransaction: com.sun.enterprise.distributedtx.UserTransactionImpl@ad9064
#]
[#2007-10-25T17:52:05.207+1000INFOsun-appserver-pe8.2javax.enterprise.system.stream.out_ThreadID=14;455737 [httpWorkerThread-2189-4] INFO  org.springframework.transaction.jta.JtaTransactionManager  - Using JTA TransactionManager: com.sun.ejb.containers.PMTransactionManagerImpl@1eafdce
#]
[#2007-10-25T17:52:26.027+1000WARNINGsun-appserver-pe8.2javax.enterprise.system.core.transaction_ThreadID=15;JTS5068: Unexpected error occurred in rollback
java.lang.NullPointerException
 at com.sun.gjc.spi.ManagedConnection.transactionCompleted(ManagedConnection.java:429)
 at com.sun.gjc.spi.XAResourceImpl.rollback(XAResourceImpl.java:140)
 at com.sun.jts.jta.TransactionState.rollback(TransactionState.java:168)
 at com.sun.jts.jtsxa.OTSResourceImpl.rollback(OTSResourceImpl.java:271)
 at com.sun.jts.CosTransactions.RegisteredResources.distributeRollback(RegisteredResources.java:971)
 at com.sun.jts.CosTransactions.TopCoordinator.rollback(TopCoordinator.java:2240)
 at com.sun.jts.CosTransactions.CoordinatorTerm.rollback(CoordinatorTerm.java:504)
 at com.sun.jts.CosTransactions.TerminatorImpl.rollback(TerminatorImpl.java:266)
 at com.sun.jts.CosTransactions.CurrentImpl.rollback(CurrentImpl.java:728)
 at com.sun.jts.jta.TransactionManagerImpl.rollback(TransactionManagerImpl.java:308)
 at com.sun.enterprise.distributedtx.J2EETransactionManagerImpl.rollback(J2EETransactionManagerImpl.java:1058)
 at com.sun.enterprise.distributedtx.J2EETransactionManagerOpt.rollback(J2EETransactionManagerOpt.java:391)
 at com.sun.ejb.containers.BaseContainer.completeNewTx(BaseContainer.java:2711)
 at com.sun.ejb.containers.BaseContainer.postInvokeTx(BaseContainer.java:2521)
 at com.sun.ejb.containers.BaseContainer.postInvoke(BaseContainer.java:819)
 at com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:137)
 at $Proxy22.processUser(Unknown Source)
 at au.net.ozgwei.services.userprocess.UserProcessServiceDelegate.processUser(UserProcessServiceDelegate.java:96)

These exceptions were really frustrating as they appeared to occur only at transaction commit time that somehow the commit failed and the EJB container was trying to roll back and then encountered an unexpected CORBA or null pointer error.

That led us to think that our configuration for Spring and Hibernate to work with EJB 2.1 was not set up properly.

Well, all that was just red herring. With debugging turned on, it was clear to us that a minor and seemingly innocent change in the web tier resulted in invoking the EJB with illegal arguments and that the POJO implementation wrapped by the EJB threw an IllegalArgumentException, which was swallowed by Sun's EJB container and triggered the transaction to be rolled back.

Once we fixed the bug at the web tier, the issue went away immediately.

So, the problem is with Sun's EJB container: when it catches a runtime exception, it should have printed the stack trace of the root cause of the exception instead of swallowing it. It wasted us several hours to figure out what went wrong.

It also taught us a few lessons:

1. Debug early on may save you many hours of code reading and googling for a problem that was hidden/eclipse by a seemingly complex problem.
2. Write more test cases for web tier codes, preferably with EasyMock 2 or jMock 2. If we had written the test cases for the UI, this problem would probably occur in the first place.

So, if you see similar JTS5031 or JTS5068 errors on Sun Application Server 8.x, make sure you do some debugging to verify that it was not caused by a runtime exception thrown by your application code...