Re: [Springframework-developer] Stale JTA transaction still attached to a thread

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Hi Juergen,

Any thoughts on this? It hasn't happened again since I reported it.

Dave

Dave Ballard wrote:

> Hi Juergen,
>
> There was a failure involving the Spring transactional cleanup code 
> which may be of interest.
>
> Background: My application architecture is in transition from 
> stateless session beans (for transaction demarcation) and entity 
> beans, to Spring managed services (and transaction demarcation) and 
> dao's. So currently, I've got a mix of both. In some cases, I've got a 
> session bean starting a transaction, then that session bean calling a 
> Spring service (resulting in the JTA transaction being joined). In 
> other newer code, Spring starts the transaction.
>
> The thread in question is ExecuteThread: '5'. The first sign of 
> trouble with this thread is a failure of an insert statement. I've 
> seen this 'PreparedStatement' exception once before a number of months 
> ago. I don't *think* this is a Hibernate bug, as the last time the 
> error involved an entity bean.  It may be a problem with my JDBC driver.
>
> Spring didn't start this transaction, but at this point in processing, 
> SessionFactoryUtils.getSession(sessionFactory, true) has been called 
> from the session bean, and a Spring managed service (with a 
> JtaTransactionManager transaction interceptor) has also been called.
>
> ---
> ERROR 13:34:55,789 [ExecuteThread: '5' for queue: 'default'] [mariew_] 
> (MoneyTransactionSessionEJB.java:459) - Error creating advance
> net.sf.hibernate.JDBCException: could not insert: 
> [LedgerEntryClass#LEN000061465159]
>    at 
> net.sf.hibernate.persister.EntityPersister.insert(EntityPersister.java:478) 
>
>    at 
> net.sf.hibernate.persister.EntityPersister.insert(EntityPersister.java:442) 
>
>    at 
> net.sf.hibernate.impl.ScheduledInsertion.execute(ScheduledInsertion.java:29) 
>
>    at net.sf.hibernate.impl.SessionImpl.executeAll(SessionImpl.java:2414)
>    at net.sf.hibernate.impl.SessionImpl.execute(SessionImpl.java:2367)
>    at net.sf.hibernate.impl.SessionImpl.flush(SessionImpl.java:2236)
>    at 
> MoneyTransactionSessionEJB.createLedgerEntriesForNewContractItems(MoneyTransactionSessionEJB.java:5661) 
>
>    at 
> MoneyTransactionSessionEJB.processTransactionInternal(MoneyTransactionSessionEJB.java:704) 
>
>    at 
> MoneyTransactionSessionEJB.processTransaction(MoneyTransactionSessionEJB.java:454) 
>
>    at 
> MoneyTransactionSessionEJB_xvjdlx_ELOImpl.processTransaction(MoneyTransactionSessionEJB_xvjdlx_ELOImpl.java:1037) 
>
>    at java.lang.reflect.Method.invoke(Native Method)
>    at 
> org.springframework.ejb.access.LocalSlsbInvokerInterceptor.invoke(LocalSlsbInvokerInterceptor.java:66) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144) 
>
>    at 
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174) 
>
>    at $Proxy126.processTransaction(Unknown Source)
>    at AdvanceCreate.execute(AdvanceCreate.java:109)
>    at AdvanceCommit.createAdvance(AdvanceCommit.java:368)
>    at AdvanceCommit.process(AdvanceCommit.java:118)
>    at 
> jsp_servlet._jsp._advance.__advance_confirm._jspService(__advance_confirm.java:125) 
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:2708) 
>
>    at 
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2427) 
>
>    at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:159)
>    at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:140)
> Caused by:
> java.sql.SQLException: [JTurbo 3.1d9 JDBC 2.1 Driver]: 
> PreparedStatement is closed
>    at com.newatlanta.jturbo.driver.u.executeUpdate(u.java)
>    at weblogic.jdbc.jts.Statement.executeUpdate(Statement.java:508)
>    at 
> net.sf.hibernate.impl.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:22) 
>
>    at 
> net.sf.hibernate.persister.EntityPersister.insert(EntityPersister.java:468) 
>
>    ... 29 more
> ---
>
> One minute later, this same thread was used for a different request 
> (the username is different):
>
> ---
> ERROR 13:35:56,805 [ExecuteThread: '5' for queue: 'default'] [dan101_] 
> (AbstractPlatformTransactionManager.java:585) - Rollback exception 
> overridden by synchronization exception
> java.lang.IllegalStateException: No value for key 
> [net.sf.hibernate.impl.SessionFactoryImpl@55f3ea] bound to thread 
> [ExecuteThread: '5' for queue: 'default']
>    at 
> org.springframework.transaction.support.TransactionSynchronizationManager.unbindResource(TransactionSynchronizationManager.java:175) 
>
>    at 
> org.springframework.orm.hibernate.SessionFactoryUtils$SpringSessionSynchronization.beforeCompletion(SessionFactoryUtils.java:871) 
>
>    at 
> org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCompletion(AbstractPlatformTransactionManager.java:580) 
>
>    at 
> org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:425) 
>
>    at 
> org.springframework.transaction.interceptor.TransactionAspectSupport.doCommitTransactionAfterReturning(TransactionAspectSupport.java:258) 
>
>    at 
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:67) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144) 
>
>    at 
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174) 
>
>    at $Proxy114.findContract(Unknown Source)
>    at AdvanceView.load(AdvanceView.java:228)
>    at AdvanceView.process(AdvanceView.java:141)
>    at 
> jsp_servlet._jsp._advance.__advanceview._jspService(__advanceview.java:139) 
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:289) 
>
>    at 
> webwork.dispatcher.ServletDispatcher.service(ServletDispatcher.java:222)
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:289) 
>
>    at 
> weblogic.servlet.jsp.PageContextImpl.forward(PageContextImpl.java:119)
>    at 
> jsp_servlet._jsp._advance.__advance_confirm._jspService(__advance_confirm.java:165) 
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:2708) 
>
>    at 
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2427) 
>
>    at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:159)
>    at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:140)
>    ---
>   There are no nested exceptions. In the previous stack trace, the 
> presentation layer called a Spring  managed service (which started its 
> own transaction).
>   After this point, each time ExecuteThread: '5' is used,  it fails 
> with a org.springframework.jdbc.UncategorizedSQLException wrapping a 
> WebLogic TimedOutException. The transaction ID (496219) is always the 
> same. This happens over and over again. As I was investigating this 
> problem, I began to ask myself "why are all of these timeouts on the 
> same thread?". Restarting the app server corrected the problem. The 
> timeout information looks like:
>      ---
>    ERROR 13:37:04,650 [ExecuteThread: '5' for queue: 'default'] 
> [torry_] (HibernateSpringContractDAO.java:235) -
>      org.springframework.jdbc.UncategorizedSQLException:
>      executing PreparedStatementCallback: encountered SQLException
>      [The transaction is no longer active (status = Rolled back.
>      [Reason=weblogic.transaction.internal.TimedOutException:
>      Transaction timed out after 29 seconds
> Xid=4954:766e8eae3c8bdd4d(496219),
>      Status=Active,numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds 
> since begin=29,
>      seconds left=30,activeThread=Thread[ExecuteThread: '5' for queue: 
> 'default',5,
>      Thread Group for Queue: 
> 'default'],ServerResourceInfo[weblogic.jdbc.jts.Connection]=
>      
> (state=started,assigned=none),SCInfo[myappserver+appserver]=(state=active), 
>
>      
> properties=({weblogic.jdbc=t3://192.168.1.1:80}),OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor= 
>
>      (CoordinatorURL=appserver+192.168.1.1:80+myappserver+, 
> Resources={})],
>      CoordinatorURL=appserver+192.168.1.1:80+myappserver+)]).
>      No further JDBC access is allowed  within this transaction.];
>      nested exception is java.sql.SQLException: The transaction is no 
> longer active
>      (status = Rolled back. 
> [Reason=weblogic.transaction.internal.TimedOutException:
>      Transaction timed out after 29 seconds
> Xid=4954:766e8eae3c8bdd4d(496219),Status=Active,
>      numRepliesOwedMe=0,numRepliesOwedOthers=0,seconds since 
> begin=29,seconds left=30,
>      activeThread=Thread[ExecuteThread: '5' for queue: 
> 'default',5,Thread Group for Queue: 'default'],
>      
> ServerResourceInfo[weblogic.jdbc.jts.Connection]=(state=started,assigned=none), 
>
>      
> SCInfo[myappserver+appserver]=(state=active),properties=({weblogic.jdbc=t3://192.168.1.1:80}), 
>
>      
> OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(CoordinatorURL=appserver+192.168.1.1:80+myappserver+, 
> Resources={})],
>      CoordinatorURL=appserver+192.168.1.1:80+myappserver+)]).
>      No further JDBC access is allowed  within this transaction.
>    ---
>      The nested exception is:
>      ---
>     ERROR 13:37:04,650 [ExecuteThread: '5' for queue: 'default'] 
> [torry_] (ServletUtils.java:221) - Error
> [trimmed verbose timeout info referencing 
> Xid=4954:766e8eae3c8bdd4d(496219)]
>    at 
> HibernateSpringContractDAO.findContract(HibernateSpringContractDAO.java:236) 
>
>    at java.lang.reflect.Method.invoke(Native Method)
>    at 
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:288) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:155) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:122) 
>
>    at 
> org.springframework.orm.hibernate.HibernateInterceptor.invoke(HibernateInterceptor.java:164) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144) 
>
>    at 
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174) 
>
>    at $Proxy93.findContract(Unknown Source)
>    at ContractServiceImpl.findContract(ContractServiceImpl.java:59)
>    at java.lang.reflect.Method.invoke(Native Method)
>    at 
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:288) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:155) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:122) 
>
>    at 
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:57) 
>
>    at 
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:144) 
>
>    at 
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:174) 
>
>    at $Proxy114.findContract(Unknown Source)
>    at AdvanceView.load(AdvanceView.java:228)
>    at AdvanceView.process(AdvanceView.java:141)
>    at 
> jsp_servlet._jsp._advance.__advanceview._jspService(__advanceview.java:139) 
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatcherImpl.java:289) 
>
>    at 
> webwork.dispatcher.ServletDispatcher.service(ServletDispatcher.java:222)
>    at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
>    at 
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:275) 
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at 
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.java:27) 
>
>    at 
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:2708) 
>
>    at 
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:2427) 
>
>    at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:159)
>    at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:140)
> Caused by:
> [trimmed verbose timeout info referencing 
> Xid=4954:766e8eae3c8bdd4d(496219)]
>    at weblogic.jdbc.jts.Connection.checkIfRolledBack(Connection.java:526)
>    at weblogic.jdbc.jts.Connection.prepareStatement(Connection.java:122)
>    at 
> org.springframework.jdbc.core.JdbcTemplate$SimplePreparedStatementCreator.createPreparedStatement(JdbcTemplate.java:992) 
>
>    at 
> org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:444)
>    at 
> org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:491)
>    at 
> org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:530)
>    at 
> org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:548)
>    at 
> org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:553)
>    at 
> HibernateSpringContractDAO.findActiveNSF(HibernateSpringContractDAO.java:716) 
>
>    at 
> HibernateSpringContractDAO.findContract(HibernateSpringContractDAO.java:231) 
>
>    ---
>    Please let me know what additional information I can provide.
>
>  Thanks again for your help,
>  Dave
>
> Juergen Hoeller wrote:
>
>> Hi Dave,
>>
>> That's indeed odd, in particular as Spring does not explicitly 
>> associate JTA
>> transactions with the current thread (of course the JTA provider 
>> itself will
>> use ThreadLocals underneath).
>>
>> The only thing that could be bound to the thread by Spring within a JTA
>> transaction is a transactional resource, such as a JDBC Connection or a
>> Hibernate Session. Such resources should _always_ get removed from the
>> thread by Spring's corresponding synchronization classes, though: So 
>> if such
>> a resource would be the root cause, this would mean some bug in Spring's
>> resource cleanup code.
>>
>> If you can track down any details, I'm gonna address this immediately 
>> (even
>> during the weekend). It would be great to clarify this before the 
>> upcoming
>> Spring 1.2.2 release...
>>
>> Juergen
>>
>>
>> -----Original Message-----
>> From: spr...@li...
>> [mailto:spr...@li...]On Behalf
>> Of Dave Ballard
>> Sent: Friday, June 17, 2005 7:06 PM
>> To: spr...@li...
>> Subject: [Springframework-developer] Stale JTA transaction still
>> attached to a tread
>>
>>
>> Hi Juergen,
>>
>> Using Spring 1.2.1 with JtaTransactionManager with WebLogic 6.1. A
>> review of my logs showed a large number of JTA timeouts. The odd thing
>> is that the timeouts seem all to be occurring on the same thread. What
>> WebLogic reports as the transaction ID is always the same.
>>
>> It appears to me that there is stale Spring JTA transaction attached to
>> this particular thread. Each time WebLogic releases this thread to a
>> request, and attempts to run some SQL (via Spring), it gets a JTA
>> timeout with the same transaction ID.
>>
>> I'm about to restart our server, and I expect this to clear up the
>> problem. However, this is a pretty serious problem. I am going to go
>> back through the logs and attempt to locate the root error for this 
>> thread.
>>
>> Thanks for your help,
>> Dave
>>
>>
>> -------------------------------------------------------
>> SF.Net email is sponsored by: Discover Easy Linux Migration Strategies
>> from IBM. Find simple to follow Roadmaps, straightforward articles,
>> informative Webcasts and more! Get everything you need to get up to
>> speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
>> _______________________________________________
>> Springframework-developer mailing list
>> Spr...@li...
>> https://lists.sourceforge.net/lists/listinfo/springframework-developer
>>
>>
>>
>> -------------------------------------------------------
>> SF.Net email is sponsored by: Discover Easy Linux Migration Strategies
>> from IBM. Find simple to follow Roadmaps, straightforward articles,
>> informative Webcasts and more! Get everything you need to get up to
>> speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
>> _______________________________________________
>> Springframework-developer mailing list
>> Spr...@li...
>> https://lists.sourceforge.net/lists/listinfo/springframework-developer
>>
>>
>>  
>>
>
>
> -------------------------------------------------------
> SF.Net email is sponsored by: Discover Easy Linux Migration Strategies
> from IBM. Find simple to follow Roadmaps, straightforward articles,
> informative Webcasts and more! Get everything you need to get up to
> speed, fast. http://ads.osdn.com/?ad_id=7477&alloc_id=16492&op=click
> _______________________________________________
> Springframework-developer mailing list
> Spr...@li...
> https://lists.sourceforge.net/lists/listinfo/springframework-developer
>
>