[Springframework-developer] Spring 1.2 Spring JTA tx timeout, tx rolls back, but no exception thrown (another race condition)

[Dave B. <dba...@on...>]

Hi Juergen,

Using unpatched Spring 1.2 on WebLogic 6.1. I've defined a 
Spring-managed service bean, with the following transaction manager and 
transaction interceptor beans:

  <bean id="MyTransactionManager" 
class="org.springframework.transaction.jta.JtaTransactionManager">
    <property 
name="transactionManagerName"><value>java:comp/UserTransaction</value></property>
  </bean>

  <bean id="MyTransactionInterceptor" 
class="org.springframework.transaction.interceptor.TransactionInterceptor">
    <property name="transactionManager"><ref 
bean="MyTransactionManager"/></property>
    <property name="transactionAttributeSource">
      <value>
        PaymentService.commit=PROPAGATION_REQUIRED,-Exception
      </value>
    </property>
  </bean>

The transactional demarcation causes a commit when the method succeeds, 
and causes a rollback when an exception is thrown (and throws the 
exception), as expected. However, if I introduce a 40 second sleep in 
the method, the transaction rolls back as expected, but sometimes no 
exception is thrown. In the case where no exception is thrown, I can see 
in the Spring log:

 WARN 14:45:03,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (EjbUtils.java:626) - START SLEEP 40: 
PaymentServiceImpl.commit() 40 seconds......
 WARN 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (EjbUtils.java:633) - DONE  SLEEP 40: 
PaymentServiceImpl.commit() 40 seconds......
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (TransactionAspectSupport.java:258) - Invoking commit for 
transaction on PaymentService.commit
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (AbstractPlatformTransactionManager.java:382) - 
Transactional code has requested rollback
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (AbstractPlatformTransactionManager.java:542) - Triggering 
beforeCompletion synchronization
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (TransactionSynchronizationManager.java:177) - Removed 
value [org.springframework.orm.hibernate.SessionHolder@57f820] for key 
[net.sf.hibernate.impl.SessionFactoryImpl@39569e] from thread 
[ExecuteThread: '30' for queue: 'default']
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (SessionFactoryUtils.java:730) - Closing Hibernate Session
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (AbstractPlatformTransactionManager.java:463) - Initiating 
transaction rollback
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (JtaTransactionManager.java:719) - Rolling back JTA transaction
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (AbstractPlatformTransactionManager.java:572) - Triggering 
afterCompletion synchronization
DEBUG 14:45:43,156 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (TransactionSynchronizationManager.java:252) - Clearing 
transaction synchronization
 INFO 14:45:43,171 [ExecuteThread: '30' for queue: 'default'] 
[edemo_acme] (PaymentCommit.java:167) - PERFORMANCE END   PaymentCommit

This is an intermittent problem that occurs in both 1.1.5 and 1.2. I run 
the same test over and over, and while it always rolls back, it only 
sometimes throws an exception. In the case where it does throw an 
exception, the log is different:

 WARN 15:18:54,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (EjbUtils.java:626) - START SLEEP 40: 
PaymentServiceImpl.commit() 40 seconds......
 WARN 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (EjbUtils.java:633) - DONE  SLEEP 40: 
PaymentServiceImpl.commit() 40 seconds......
DEBUG 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (TransactionAspectSupport.java:241) - Invoking commit for 
transaction on method 'commit' in class [PaymentService]
DEBUG 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (AbstractPlatformTransactionManager.java:523) - Triggering 
beforeCommit synchronization
DEBUG 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (SessionFactoryUtils.java:809) - Flushing Hibernate session 
on transaction synchronization
DEBUG 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (SQLErrorCodeSQLExceptionTranslator.java:225) - Unable to 
translate SQLException with errorCode '0', will now try the fallback 
translator
DEBUG 15:19:34,109 [ExecuteThread: '31' for queue: 'default'] 
[edemo_acme] (SQLStateSQLExceptionTranslator.java:74) - Translating 
SQLException with SQLState 'null' and errorCode '0' and message [The 
transaction is no longer active (status = Rolled back. 
[Reason=weblogic.transaction.internal.TimedOutException: Transaction 
timed out after 28 seconds
[snip]

This appears to be another race condition. In the case where the 
exception is thrown, the transaction has not yet been flagged as 
rollback-only. The code proceeds to attempt a hibernate flush(), and 
this causes a SQLException(TimedOutException) to be thrown.

In the first case where no exception is thrown, the transaction has 
already been flagged rollback-only, so the code never calls hibernate 
flush, and simply returns w/o an exception after rolling back the tx.

This is a pretty serious problem for my application because the calling 
code has no idea that the transaction rolled back.

Thanks,
Dave