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

As I said a couple of days ago, the potential for follow-up errors has been
removed: no dangling thread-bound resource can remain in any case now, not
even in case of internal assertion failures.

Why that assertion (that you encountered) failed in the first place is still
unclear. But at least the effect of such an assertion failure has been
reduced to the transaction that caused it now.

Juergen

-----Original Message-----
From: spr...@li...
[mailto:spr...@li...] On Behalf Of
Dave Ballard
Sent: Friday, June 24, 2005 6:47 PM
To: spr...@li...
Subject: Re: [Springframework-developer] Stale JTA transaction still
attached to a thread

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.ja
> va: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(Mone
> yTransactionSessionEJB.java:5661)
>
>    at
> MoneyTransactionSessionEJB.processTransactionInternal(MoneyTransaction
> SessionEJB.java:704)
>
>    at
> MoneyTransactionSessionEJB.processTransaction(MoneyTransactionSessionE
> JB.java:454)
>
>    at
> MoneyTransactionSessionEJB_xvjdlx_ELOImpl.processTransaction(MoneyTran
> sactionSessionEJB_xvjdlx_ELOImpl.java:1037)
>
>    at java.lang.reflect.Method.invoke(Native Method)
>    at
> org.springframework.ejb.access.LocalSlsbInvokerInterceptor.invoke(Loca
> lSlsbInvokerInterceptor.java:66)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:144)
>
>    at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic
> AopProxy.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_conf
> irm.java:125)
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppSer
> vletContext.java:2708)
>
>    at
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImp
> l.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.TransactionSynchronizationMana
> ger.unbindResource(TransactionSynchronizationManager.java:175)
>
>    at
> org.springframework.orm.hibernate.SessionFactoryUtils$SpringSessionSyn
> chronization.beforeCompletion(SessionFactoryUtils.java:871)
>
>    at
> org.springframework.transaction.support.AbstractPlatformTransactionMan
> ager.triggerBeforeCompletion(AbstractPlatformTransactionManager.java:5
> 80)
>
>    at
> org.springframework.transaction.support.AbstractPlatformTransactionMan
> ager.commit(AbstractPlatformTransactionManager.java:425)
>
>    at
> org.springframework.transaction.interceptor.TransactionAspectSupport.d
> oCommitTransactionAfterReturning(TransactionAspectSupport.java:258)
>
>    at
> org.springframework.transaction.interceptor.TransactionInterceptor.inv
> oke(TransactionInterceptor.java:67)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:144)
>
>    at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic
> AopProxy.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(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatc
> herImpl.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(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatc
> herImpl.java:289)
>
>    at
> weblogic.servlet.jsp.PageContextImpl.forward(PageContextImpl.java:119)
>    at
> jsp_servlet._jsp._advance.__advance_confirm._jspService(__advance_conf
> irm.java:165)
>
>    at weblogic.servlet.jsp.JspBase.service(JspBase.java:27)
>    at
> weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppSer
> vletContext.java:2708)
>
>    at
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImp
> l.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=act
> ive),
>
>      
> properties=({weblogic.jdbc=t3://192.168.1.1:80}),OwnerTransactionManag
> er=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,assign
> ed=none),
>
>      
> SCInfo[myappserver+appserver]=(state=active),properties=({weblogic.jdb
> c=t3://192.168.1.1:80}),
>
>      
> OwnerTransactionManager=ServerTM[ServerCoordinatorDescriptor=(Coordina
> torURL=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.jav
> a:236)
>
>    at java.lang.reflect.Method.invoke(Native Method)
>    at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflectio
> n(AopUtils.java:288)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoi
> npoint(ReflectiveMethodInvocation.java:155)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:122)
>
>    at
> org.springframework.orm.hibernate.HibernateInterceptor.invoke(Hibernat
> eInterceptor.java:164)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:144)
>
>    at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic
> AopProxy.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.invokeJoinpointUsingReflectio
> n(AopUtils.java:288)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoi
> npoint(ReflectiveMethodInvocation.java:155)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:122)
>
>    at
> org.springframework.transaction.interceptor.TransactionInterceptor.inv
> oke(TransactionInterceptor.java:57)
>
>    at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(R
> eflectiveMethodInvocation.java:144)
>
>    at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamic
> AopProxy.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(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.RequestDispatcherImpl.forward(RequestDispatc
> herImpl.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(ServletStubImp
> l.java:275)
>
>    at weblogic.servlet.internal.TailFilter.doFilter(TailFilter.java:21)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at AccessControlFilter.doFilterInternal(AccessControlFilter.java:186)
>    at AccessControlFilter.doFilter(AccessControlFilter.java:79)
>    at
> weblogic.servlet.internal.FilterChainImpl.doFilter(FilterChainImpl.jav
> a:27)
>
>    at
> weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppSer
> vletContext.java:2708)
>
>    at
> weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImp
> l.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$SimplePreparedStatementCrea
> tor.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.ja
> va:716)
>
>    at
> HibernateSpringContractDAO.findContract(HibernateSpringContractDAO.jav
> a: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-develope
>> r
>>
>>
>>
>> -------------------------------------------------------
>> 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-develope
>> r
>>
>>
>>  
>>
>
>
> -------------------------------------------------------
> 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