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

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

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
>
>
>  
>