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

I've tracked this down as far as why the old Connection handle (with the old
transaction id) was still hanging around with that thread.  This is
definitely a follow-up error to the unexpected

  java.lang.IllegalStateException: No value for key
  [net.sf.hibernate.impl.SessionFactoryImpl@55f3ea] bound to thread

that came before. Through an unfortunate cascade, such an expected error can
lead to some transaction synchronizations not getting fully executed: in
your case, a ConnectionSynchronization that is supposed to remove the
transactional JDBC Connection handle from the thread.

I've fixed this already: All synchronizations will now get fully executed,
even when some internal transaction synchronization throws an unexpected
assertion failure. This should completely remove the potential for such
follow-up errors, leaving all threads fully intact even in awkward
unexpected cases.

In other words, you won't get dangling transactional resources hanging
around with your threads anymore, not even when some internal assertions
within Spring's own transaction synchronization code fail. In all other
cases, you wouldn't get dangling transactional resources in the first place;
this really only affects our corner case here.

Which leads me to the root question: Why did you get that
IllegalStateException in the first place? Some code must have removed the
SessionHolder from the thread within the transaction: Spring's
synchronization code bound a SessionHolder to the thread at transaction
begin, but couldn't find it anymore at transaction completion.

The obvious cause would be some "TransactionSynchronization.unbindResource"
call in your application, but I doubt that this is the case. It rather seems
that some specific transaction interaction scenario can cause preliminary
unbinding of the SessionHolder, causing the assertion failure in the
surrounding transaction synchronization code.

So in summary, the potential for follow-up errors has been removed: no
dangling thread-bound resource in any case, not even in case of internal
assertion failures. Why that assertion 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 17, 2005 10:45 PM
To: spr...@li...
Subject: Re: [Springframework-developer] Stale JTA transaction still
attached to a tread

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(MoneyTrans
actionSessionEJB.java:5661)
    at
MoneyTransactionSessionEJB.processTransactionInternal(MoneyTransactionSessio
nEJB.java:704)
    at
MoneyTransactionSessionEJB.processTransaction(MoneyTransactionSessionEJB.jav
a:454)
    at
MoneyTransactionSessionEJB_xvjdlx_ELOImpl.processTransaction(MoneyTransactio
nSessionEJB_xvjdlx_ELOImpl.java:1037)
    at java.lang.reflect.Method.invoke(Native Method)
    at
org.springframework.ejb.access.LocalSlsbInvokerInterceptor.invoke(LocalSlsbI
nvokerInterceptor.java:66)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:144)
    at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.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.ja
va: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(WebAppServletCo
ntext.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.un
bindResource(TransactionSynchronizationManager.java:175)
    at
org.springframework.orm.hibernate.SessionFactoryUtils$SpringSessionSynchroni
zation.beforeCompletion(SessionFactoryUtils.java:871)
    at
org.springframework.transaction.support.AbstractPlatformTransactionManager.t
riggerBeforeCompletion(AbstractPlatformTransactionManager.java:580)
    at
org.springframework.transaction.support.AbstractPlatformTransactionManager.c
ommit(AbstractPlatformTransactionManager.java:425)
    at
org.springframework.transaction.interceptor.TransactionAspectSupport.doCommi
tTransactionAfterReturning(TransactionAspectSupport.java:258)
    at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(Tr
ansactionInterceptor.java:67)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:144)
    at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.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(RequestDispatcherImp
l.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(RequestDispatcherImp
l.java:289)
    at
weblogic.servlet.jsp.PageContextImpl.forward(PageContextImpl.java:119)
    at
jsp_servlet._jsp._advance.__advance_confirm._jspService(__advance_confirm.ja
va: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(WebAppServletCo
ntext.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=Ser
verTM[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=non
e),

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(AopU
tils.java:288)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint
(ReflectiveMethodInvocation.java:155)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:122)
    at
org.springframework.orm.hibernate.HibernateInterceptor.invoke(HibernateInter
ceptor.java:164)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:144)
    at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.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(AopU
tils.java:288)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint
(ReflectiveMethodInvocation.java:155)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:122)
    at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(Tr
ansactionInterceptor.java:57)
    at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(Reflect
iveMethodInvocation.java:144)
    at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopPro
xy.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(RequestDispatcherImp
l.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(WebAppServletCo
ntext.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.cr
eatePreparedStatement(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