Bug 1028501

Summary: Connections seems to be shared between transactions
Product: [JBoss] JBoss Enterprise Application Platform 6 Reporter: Ståle W. Pedersen <spederse>
Component: JCA, Transaction ManagerAssignee: Jesper Pedersen <jpederse>
Status: CLOSED CURRENTRELEASE QA Contact: Ondrej Chaloupka <ochaloup>
Severity: high Docs Contact: Russell Dickenson <rdickens>
Priority: unspecified    
Version: 6.2.0CC: anmiller, brian.stansberry, dandread, jason.greene, jawilson, jdoyle, jkudrnac, johara, jolee, jpederse, jwhiting, myarboro, ochaloup, pslavice, smaestri, smarlow, tom.jenkinson
Target Milestone: CR3   
Target Release: EAP 6.2.0   
Hardware: x86_64   
OS: Linux   
URL: http://pad.engineering.redhat.com/K6S5J3zdhm
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-12-15 16:16:20 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1032740    
Attachments:
Description Flags
Well behaving Connection
none
Connection with wrong state.
none
IronJacamar Core Impl with extra WARNs
none
IronJacamar Core Impl with new TransactionSynchronizer API/Impl
none
IronJacamar Core Impl with new TransactionSynchronizer API/Impl none

Description Ståle W. Pedersen 2013-11-08 15:43:40 UTC
While trying to run a benchmark on EAP6.2 ER7 we get this exception: 

http://pastebin.test.redhat.com/175107

It did not occur on EAP6.1

Comment 4 Brian Stansberry 2013-11-08 21:33:10 UTC
Can you comment on why you believe this indicates "Connections seems to be shared between transactions"? It's not obvious from the stack trace.

Comment 6 tom.jenkinson 2013-11-09 14:58:52 UTC
I had a conversation with Will Reichert yesterday. It looked like for some reason interleaving is not enabled for the postgres datasource. I couldn't help him too much I mentioned that Jesper would probably need a log that confirms whether or not trackbytx was on for that datasource - from the code it certainly appeared as though it wasn't:

https://github.com/ironjacamar/ironjacamar/blob/ironjacamar-1.0.21.Final/core/src/main/java/org/jboss/jca/core/connectionmanager/listener/TxConnectionListener.java#L346

Should only happen if !isTrackByTx and this datasource is not marked as interleaving (as I was informed at least) so that should be set to true as per:
https://github.com/ironjacamar/ironjacamar/blob/ironjacamar-1.0.21.Final/core/src/main/java/org/jboss/jca/core/connectionmanager/tx/TxConnectionManagerImpl.java#L387

This was the case for old versions of JBoss at least from my grep of the internet:
http://forum.spring.io/forum/spring-projects/data/25910-jtatransactionmanager-postgresql-8-1-and-jboss-4-0-5-problem

Main thing is to debug it and work out why it is going in the !trackByTx path I would say, hopefully just a config issue. Maybe EAP docs have some info?

Comment 7 Jeremy Whiting 2013-11-09 18:46:14 UTC
 This is an example of when the TxConnectionListener.delist method is calling the jdbc driver with the XAResource.TMSUSPEND flag.

Breakpoint hit: "thread=Thread-28 (HornetQ-client-global-threads-2109721565)", org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.delist(), line=346 bci=126
346                   boolean suspendResult = tx.delistResource(getXAResource(), XAResource.TMSUSPEND);

Thread-28 (HornetQ-client-global-threads-2109721565)[1] locals
Method arguments:
Local variables:
tx = instance of com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple(id=15027)
synchronization = instance of org.jboss.jca.core.connectionmanager.listener.TxConnectionListener$TransactionSynchronization(id=15028)
Thread-28 (HornetQ-client-global-threads-2109721565)[1] where
  [1] org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.delist (TxConnectionListener.java:346)
  [2] org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed (TxConnectionListener.java:412)
  [3] org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle (BaseWrapperManagedConnection.java:574)
  [4] org.jboss.jca.adapters.jdbc.WrappedConnection.close (WrappedConnection.java:265)
  [5] org.hibernate.service.jdbc.connections.internal.DatasourceConnectionProviderImpl.closeConnection (DatasourceConnectionProviderImpl.java:148)
  [6] org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.releaseConnection (AbstractSessionImpl.java:297)
  [7] org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.releaseConnection (LogicalConnectionImpl.java:241)
  [8] org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.afterStatementExecution (JdbcCoordinatorImpl.java:259)
  [9] org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.flushEnding (JdbcCoordinatorImpl.java:166)
  [10] org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions (AbstractFlushingEventListener.java:343)
  [11] org.hibernate.event.internal.DefaultFlushEventListener.onFlush (DefaultFlushEventListener.java:52)
  [12] org.hibernate.internal.SessionImpl.flush (SessionImpl.java:1,240)
  [13] org.hibernate.internal.SessionImpl.managedFlush (SessionImpl.java:404)
  [14] org.hibernate.engine.transaction.synchronization.internal.SynchronizationCallbackCoordinatorImpl.beforeCompletion (SynchronizationCallbackCoordinatorImpl.java:113)
  [15] org.hibernate.engine.transaction.synchronization.internal.RegisteredSynchronization.beforeCompletion (RegisteredSynchronization.java:53)
  [16] com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.beforeCompletion (SynchronizationImple.java:76)
  [17] com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.beforeCompletion (TwoPhaseCoordinator.java:273)
  [18] com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end (TwoPhaseCoordinator.java:93)
  [19] com.arjuna.ats.arjuna.AtomicAction.commit (AtomicAction.java:162)
  [20] com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate (TransactionImple.java:1,165)
  [21] com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit (BaseTransaction.java:126)
  [22] com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit (BaseTransactionManagerDelegate.java:75)
  [23] org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction (CMTTxInterceptor.java:92)
  [24] org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx (CMTTxInterceptor.java:276)
  [25] org.jboss.as.ejb3.tx.CMTTxInterceptor.requiresNew (CMTTxInterceptor.java:363)
  [26] org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation (CMTTxInterceptor.java:240)
  [27] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [28] org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation (CurrentInvocationContextInterceptor.java:41)
  [29] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [30] org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation (ShutDownInterceptorFactory.java:64)
  [31] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [32] org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation (LoggingInterceptor.java:59)
  [33] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [34] org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation (NamespaceContextInterceptor.java:50)
  [35] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [36] org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation (AdditionalSetupInterceptor.java:55)
  [37] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [38] org.jboss.as.ee.component.TCCLInterceptor.processInvocation (TCCLInterceptor.java:45)
  [39] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [40] org.jboss.invocation.ChainedInterceptor.processInvocation (ChainedInterceptor.java:61)
  [41] org.jboss.as.ee.component.ViewService$View.invoke (ViewService.java:165)
  [42] org.jboss.as.ee.component.ViewDescription$1.processInvocation (ViewDescription.java:182)
  [43] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [44] org.jboss.invocation.ChainedInterceptor.processInvocation (ChainedInterceptor.java:61)
  [45] org.jboss.as.ee.component.ProxyInvocationHandler.invoke (ProxyInvocationHandler.java:72)
  [46] org.spec.jent.ejb.mfg.session.WorkOrderSessionLocal$$$view32.scheduleWorkOrder (null)
  [47] org.spec.jent.ejb.mfg.mdb.LargerOrderMDB.onMessage (LargerOrderMDB.java:55)
  [48] sun.reflect.GeneratedMethodAccessor148.invoke (null)
  [49] sun.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
  [50] java.lang.reflect.Method.invoke (Method.java:606)
  [51] org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation (ManagedReferenceMethodInterceptorFactory.java:72)
  [52] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [53] org.jboss.invocation.WeavedInterceptor.processInvocation (WeavedInterceptor.java:53)
  [54] org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation (UserInterceptorFactory.java:58)
  [55] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [56] org.jboss.invocation.WeavedInterceptor.processInvocation (WeavedInterceptor.java:53)
  [57] org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation (UserInterceptorFactory.java:58)
  [58] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [59] org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation (ExecutionTimeInterceptor.java:43)
  [60] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [61] org.jboss.invocation.InitialInterceptor.processInvocation (InitialInterceptor.java:21)
  [62] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [63] org.jboss.invocation.ChainedInterceptor.processInvocation (ChainedInterceptor.java:61)
  [64] org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation (ComponentDispatcherInterceptor.java:53)
  [65] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [66] org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation (PooledInstanceInterceptor.java:51)
  [67] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [68] org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx (CMTTxInterceptor.java:250)
  [69] org.jboss.as.ejb3.tx.CMTTxInterceptor.required (CMTTxInterceptor.java:341)
  [70] org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation (CMTTxInterceptor.java:238)
  [71] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [72] org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation (CurrentInvocationContextInterceptor.java:41)
  [73] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [74] org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation (ShutDownInterceptorFactory.java:64)
  [75] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [76] org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation (LoggingInterceptor.java:59)
  [77] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [78] org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation (NamespaceContextInterceptor.java:50)
  [79] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [80] org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation (AdditionalSetupInterceptor.java:55)
  [81] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [82] org.jboss.as.ejb3.component.messagedriven.MessageDrivenComponentDescription$5$1.processInvocation (MessageDrivenComponentDescription.java:203)
  [83] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [84] org.jboss.as.ee.component.TCCLInterceptor.processInvocation (TCCLInterceptor.java:45)
  [85] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [86] org.jboss.invocation.ChainedInterceptor.processInvocation (ChainedInterceptor.java:61)
  [87] org.jboss.as.ee.component.ViewService$View.invoke (ViewService.java:165)
  [88] org.jboss.as.ee.component.ViewDescription$1.processInvocation (ViewDescription.java:182)
  [89] org.jboss.invocation.InterceptorContext.proceed (InterceptorContext.java:288)
  [90] org.jboss.invocation.ChainedInterceptor.processInvocation (ChainedInterceptor.java:61)
  [91] org.jboss.as.ee.component.ProxyInvocationHandler.invoke (ProxyInvocationHandler.java:72)
  [92] javax.jms.MessageListener$$$view13.onMessage (null)
  [93] sun.reflect.GeneratedMethodAccessor92.invoke (null)
  [94] sun.reflect.DelegatingMethodAccessorImpl.invoke (DelegatingMethodAccessorImpl.java:43)
  [95] java.lang.reflect.Method.invoke (Method.java:606)
  [96] org.jboss.as.ejb3.inflow.MessageEndpointInvocationHandler.doInvoke (MessageEndpointInvocationHandler.java:140)
  [97] org.jboss.as.ejb3.inflow.AbstractInvocationHandler.invoke (AbstractInvocationHandler.java:73)
  [98] com.sun.proxy.$Proxy104.onMessage (null)
  [99] org.hornetq.ra.inflow.HornetQMessageHandler.onMessage (HornetQMessageHandler.java:319)
  [100] org.hornetq.core.client.impl.ClientConsumerImpl.callOnMessage (ClientConsumerImpl.java:1,117)
  [101] org.hornetq.core.client.impl.ClientConsumerImpl.access$500 (ClientConsumerImpl.java:57)
  [102] org.hornetq.core.client.impl.ClientConsumerImpl$Runner.run (ClientConsumerImpl.java:1,252)
  [103] org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run (OrderedExecutorFactory.java:107)
  [104] java.util.concurrent.ThreadPoolExecutor.runWorker (ThreadPoolExecutor.java:1,145)
  [105] java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:615)
  [106] java.lang.Thread.run (Thread.java:744)

 To access the trapped line 346 here https://github.com/ironjacamar/ironjacamar/blob/ironjacamar-1.0.21.Final/core/src/main/java/org/jboss/jca/core/connectionmanager/listener/TxConnectionListener.java#L346

 there need to be a couple of true conditions for the if control statement  block of code to execute.
a) The first is the negation of isTrackByTx() 
b) the second transactionSynchronization reference is not null.

 I have been told to expect the default configuration is to track connections by transaction to be enabled. Unless disabled with the <interlace/> tag. Therefore the call to isTrackByTx() *should* always be true for the application we are using. The if block should never be executed.

Comment 8 Jesper Pedersen 2013-11-11 03:07:33 UTC
I'm devel_ack- this one, since there is no TRACE logging nor configuration attached. See minimum requirements for creating a ticket here: https://docspace.corp.redhat.com/docs/DOC-101004#Logging_categories

In the future, do a forum post with the data.

Most likely scenario: lazy enlistment of a connection from a resource with use-ccm="false".

Comment 12 Jeremy Whiting 2013-11-11 16:50:55 UTC
 I tried configuring all the datasources (four of them) with use-ccm="true". This did not make a difference. Still seeing TMSUSPEND being passed to the pgjdbc driver.

 Also tried running the server with TRACE logging on the three categories. This kills performance sufficiently that the issue no longer occurs. The server no longer report reports error. Which suggests this is a timing issue.

 I will attempt again using a tmpfs for logging file storage to see if this improves performance sufficiently to recreate the issue and capture the necessary information.

Comment 13 Jesper Pedersen 2013-11-12 02:40:33 UTC
Sounds like DMR handling of default values then - try and add an explicit <interleaving>false</interleaving> in the <xa-pool> configuration.

org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl will log interleaving status at TRACE once a connection is created.

Comment 14 Jesper Pedersen 2013-11-12 04:39:07 UTC
In addition, add org.jboss.as.connector.subsystems.datasources @ TRACE

Comment 15 Jeremy Whiting 2013-11-12 10:14:37 UTC
 These logging categories are very verbose. With these levels of logging the issue being investigated goes away.
 Trying again with 

org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$AS7DataSourceDeployer
and
org.jboss.jca.core.connectionmanager.TxConnectionManager

 that has been suggested on IRC.

Comment 17 Ståle W. Pedersen 2013-11-12 14:43:01 UTC
the <interleaving> attribute do not have any value defined to it. afaik setting it turn interleaving on, not having it there set interleaving to false.

(In reply to Jesper Pedersen from comment #13)
> Sounds like DMR handling of default values then - try and add an explicit
> <interleaving>false</interleaving> in the <xa-pool> configuration.
> 
> org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl will log
> interleaving status at TRACE once a connection is created.

Comment 18 Ståle W. Pedersen 2013-11-12 14:46:53 UTC
the schema info:
<xs:element name="interleaving" type="boolean-presenceType" minOccurs="0">
  <xs:annotation>
    <xs:documentation>
      <![CDATA[[
        An element to enable interleaving for XA connection factories Ex: <interleaving/>
      ]]> 
    </xs:documentation>
  </xs:annotation>
</xs:element>

Comment 21 Ståle W. Pedersen 2013-11-12 14:59:36 UTC
extra info regarding this. here's the method thats parsing the xml:
https://github.com/ironjacamar/ironjacamar/blob/1.0/common/src/main/java/org/jboss/jca/common/metadata/ds/v11/DsParser.java#LC468
the interleaving attribute is set to false here:
https://github.com/ironjacamar/ironjacamar/blob/1.0/common/src/main/java/org/jboss/jca/common/api/metadata/Defaults.java#L97

(In reply to Jesper Pedersen from comment #13)
> Sounds like DMR handling of default values then - try and add an explicit
> <interleaving>false</interleaving> in the <xa-pool> configuration.
> 
> org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl will log
> interleaving status at TRACE once a connection is created.

Comment 22 Jeremy Whiting 2013-11-12 17:46:42 UTC
 To debug this further some code was added to the enlist method. Rather than using TRACE logging.
 https://github.com/ironjacamar/ironjacamar/blob/ironjacamar-1.0.21.Final/core/src/main/java/org/jboss/jca/core/connectionmanager/listener/TxConnectionListener.java#L140

*** added code begin  ****
      if (!isTrackByTx()) 
      {
    	  log.info("Potential problem, isTrackByTx() is false.");
      }
*** added code end ****

 The sever logs show the state of org.jboss.jca.core.connectionmanager.listener.AbstractConnectionListener.trackByTx to be false at the start of enlistment of the Connection object.

12:32:55,637 INFO  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-205 (HornetQ-client-global-threads-1774321399)) Potential problem, isTrackByTx() is false.
12:32:55,642 WARN  [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (Thread-205 (HornetQ-client-global-threads-1774321399)) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6d239add[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@22d2c905 connection handles=0 lastUse=1384277575636 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@587b3f61 pool internal context=SemaphoreArrayListManagedConnectionPool@141dde1b[pool=SPECjMfgDS] xaResource=XAResourceWrapperImpl@6ecccd12[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@22d2c905 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.2.1.3 jndiName=java:/jdbc/SPECjMfgDS] txSync=null]: org.postgresql.xa.PGXAException: suspend/resume not implemented
        at org.postgresql.xa.PGXAConnection.end(PGXAConnection.java:255)
        at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:295)
        at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.end(XAResourceWrapperImpl.java:114)
        at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.delistResource(TransactionImple.java:869)
        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.delist(TxConnectionListener.java:351)
        at org.jboss.jca.core.connectionmanager.listener.TxConnectionListener.connectionClosed(TxConnectionListener.java:417)
        at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.closeHandle(BaseWrapperManagedConnection.java:574)

 Investigation will be made to identify how far this problem extends. Is it a single component or across the board ?

Comment 23 Jeremy Whiting 2013-11-12 22:01:20 UTC
 The issue is occurring across several components in the system when the transaction is completing and releasing the Connection.

 The next task is to add logging during enlistment to dump the call stack. This should give some context to how the situation arose.

Comment 24 Jeremy Whiting 2013-11-12 23:51:58 UTC
 Attached are two files. Each is an example call stack showing both are near identical. 
 The file "info-enlist-with-correct-state-03.txt" is a well behaving execution. Whereas "info-enlist-with-wrong-state.txt" is for a failure.

 Apart from the difference in the enlist method which is due to extra logging they are identical. While this indicates both executing threads have the same code path it is not conclusive.
 A Byteman script to detect which thread is modifying the state of AbstractConnectionListener.trackByTx is the next step to investigate this.

Comment 25 Jeremy Whiting 2013-11-12 23:53:27 UTC
Created attachment 823197 [details]
Well behaving Connection

Comment 26 Jeremy Whiting 2013-11-12 23:54:21 UTC
Created attachment 823198 [details]
Connection with wrong state.

Comment 27 Jeremy Whiting 2013-11-13 16:16:57 UTC
 Using Byteman scripts the fact that trackByTx is false on delist() has been identified. This occurs for EAP 6.1 and EAP 6.2.

 The reason for TMSUSPEND to be passed intermittently to the pgjdbc driver in 6.2 is the TxConnectionListener.transactionSynchronization field is not null. Allowing the code to reach #346.

 It is the 2nd condition at the bottom of Comment #7.

Comment 47 Jeremy Whiting 2013-11-14 23:54:11 UTC
 The focus today has been to identify the reason for the wrong trackByTx state.

 Currently the JCA will set the correct state in 2 situations:
a) At the beginning of a Transaction 
b) When the CachedConnectionManager is enabled. The the application tested with does not have the CCM enabled.

 This leaves the situation of when a Connection is allocated for an in-flight transaction it will not have trackByTx set to true.

Comment 48 tom.jenkinson 2013-11-15 09:38:51 UTC
Does this affect any of the earlier ER builds do you know?

Comment 50 Jesper Pedersen 2013-11-17 05:28:46 UTC
This isn't easy to follow, since BZ isn't a threaded communication medium.

The dump trace is interesting for more than one reason.

I know that Hibernate used to do work in Synchronization.afterCompletion() which is completely unsafe, since the physical connection could have been returned to the pool (done in afterCompletion(int) by IJ). The JTA spec doesn't allow explicit ordering, so the IronJacamar Synchronization could be been fired first. Luckily the JDBC resource adapter detects this, dump a WARN, and kills the connection.

IronJacamar 1.0 "suffers" from a missing XAResource lifecycle notification, namely delistResource(xyz, TMSUCCESS). This has been fixed in IronJacamar 1.1, but not considered safe enough to back-port. It is an interesting sidenote, since we can't assume ordering of beforeCompletion() calls either. Something to note, not related to this BZ in general.

@Jeremy - We need the full stack trace once XAResource.end(xyz, TMSUSPEND) is called. Then we need the information about the components in that trace with their transaction property (REQUIRED, REQUIRES_NEW, ...). Ideally, with TRACE logging, but otherwise we will have to expand the Byteman rule. BTW, the current dumps doesn't align with the source, what was changed ? And some logs says WS, while others say HornetQ-client - so provide separate dumps for each of the failing scenarios.

@Stale - WildFly / EAP doesn't have a present type, so <interleaving>false</interleaving> will work.

@Scott - Could you check if the afterCompletion(int) -> beforeCompletion() change happend in EAP 6.2 ?

@Pavel - Sidenote, we need to make sure that there are test cases for all external clients, not going through the web container, that CCM resources are working as expected. Ping through forum, or off BZ for additional details.

Anyway, work branch is

https://github.com/jesperpedersen/ironjacamar/tree/BZ1028501

Currently with 3 simple test cases - all passing.

Scott have also provided a patch to enable more information when the error occurs. A log from that run would be nice too.

Looking at the current logs both Narayana and IronJacamar does the right thing: tx.rollback() + kills the connection. So, no data loss.

Comment 52 Jesper Pedersen 2013-11-18 03:36:56 UTC
@Jeremy - Are you seeing transaction timeouts ?

Comment 53 Jesper Pedersen 2013-11-18 06:46:10 UTC
@Jeremy - Please, add

<background-validation>true</background-validation>
<background-validation-millis>60000</background-validation-millis>

to all <validation> elements.

Comment 54 Jesper Pedersen 2013-11-18 06:47:08 UTC
@Jeremy - Are there any connection errors leading up to the error ?

Comment 55 Ståle W. Pedersen 2013-11-18 07:18:23 UTC
@Jesper, no

Comment 56 Jeremy Whiting 2013-11-18 10:04:05 UTC
@ Jesper, no connection timeouts nor connection errors are occurring.

Comment 57 Dimitris Andreadis 2013-11-18 16:50:37 UTC
Added the etherpad URL, too.

Comment 68 Jesper Pedersen 2013-11-19 06:03:16 UTC
Created attachment 825903 [details]
IronJacamar Core Impl with extra WARNs

Comment 71 John O'Hara 2013-11-19 10:57:52 UTC
when running with ironjacamar-core-impl-extra-warns.jar (attachment 825903 [details]), the WARN messages  (org.postgresql.xa.PGXAException: suspend/resume not implemented) were not thrown during tests. Additional WARN messages were logged when EAP was shutdown.


05:28:53,758 WARN  [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] (ServerService Thread Pool -- 69) DESTROYED: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1ef7df3a[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@236068b8 connection handles=0 lastUse=1384855647854 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@74edb45e pool internal context=SemaphoreArrayListManagedConnectionPool@7a97c7dc[pool=XXXXXX] xaResource=XAResourceWrapperImpl@e7b1a2d[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@236068b8 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.2.1.3 jndiName=java:/jdbc/XXXXXX] txSync=null]: java.lang.Exception

Comment 84 Jesper Pedersen 2013-11-20 04:09:03 UTC
Created attachment 826412 [details]
IronJacamar Core Impl with new TransactionSynchronizer API/Impl

Comment 87 Jesper Pedersen 2013-11-20 07:29:29 UTC
Created attachment 826459 [details]
IronJacamar Core Impl with new TransactionSynchronizer API/Impl

Comment 102 Dimitris Andreadis 2013-11-20 16:42:30 UTC
I think we should be breaking on the first match, good catch.

Comment 110 Jason T. Greene 2013-11-20 23:28:53 UTC
Here is the patch, completely untested:
https://github.com/n1hility/ironjacamar/commit/48aad2ae413422fb6ab4c09f36da5d6cab824c7e