Transactions from @Remote annotated EJB sometimes not commited
hans.christian.goranson Jan 20, 2017 9:59 AMI have a problem with a transaction not being committed and the db connections not being released in my web application which runs with Wildfly 10.1 and uses Narayana and IronJacamar together with a postgres db.
This causes the connection pool to run out of connection after a while. The issue started to occur after we updated Wildfly from 9 to 10.
I'm not sure if this is a Narayana related issue or not but I would like to understand some transaction related things I see in the logs
The scenario is that I have different EJBs packaged in different ear files which communicates with eachother using JNDI lookup. Each ear has its own persistence context but uses the same datasource and database.
I start a transaction from a @Local annotated EJB bean (lets call it CrmEJB) in crm.ear, this calls a @Remote anotated bean (lets call it PriceEJB) in price.ear.
The transaction scope is default (REQUIRED) everywhere so I expect (I'm not sure if this is a correct assumption) the transaction to be propagated from CrmBean to PriceEJB.
For this scenario, all queries to the database are SELECT queries (so it is just database reads)
The problem is that around every fifth time, the PriceEJB aquires a new connection from the connection pool, and begins a new transaction but never commits. So that connection will never never be put back into the pool.
After enabling some TRACE logs for arjuna and compare a successful scenario with a failure scenario, I can see that for failure cases, two different versions of the class TransactionImple is used, where one is from the subordinate folder
The CrmBean which starts the transaction uses the class
/narayana/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/TransactionImple.java
while the PriceBean uses the class
/narayana/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/subordinate/jca/TransactionImple.java
When I enabled JTS in the configuration, I do not experience the problem anymore and everything works fine, but I'm not sure if this has any side effects
My questions are:
- Can the different classes of TransactionImple have something to do with the problem? if so some hints what could be wrong and maybe some tips where to continue the investigation (I'm not particularly familiar with Narayana and transactions so any background information is welcome)
- shall I have JTS enabled for ear to ear communication within the same app server with @Remote annotated EJB?
I can see some different behaviour of the PriceEJB, sometimes it is running as a separate thread and sometime it is the same thread running as CrmBean.
I also had successful cases where the TransactionImple comes both from the arjunacore folder and subordinate folder
For both failure and success cases, I can see this in the log: "SubordinationManager.setTxType(JTA)"
My configuration looks like this (if have tried to set interleaving and tracking to true without any differences):
XA datasource | Transactions | JCA |
---|---|---|
<xa-datasource jndi-name="java:jboss/datasources/postgres-crm-ds" pool-name="postgres-crm-ds" statistics-enabled="true" > <driver>postgresql-9.4.1212.jar</driver> <xa-datasource-property name="ServerName">...</xa-datasource-property> <xa-datasource-property name="PortNumber">...</xa-datasource-property> <xa-datasource-property name="DatabaseName">...</xa-datasource-property>
<xa-datasource-class>org.postgresql.xa.PGXADataSource</xa-datasource-class> <xa-pool> <min-pool-size>1</min-pool-size> <max-pool-size>400</max-pool-size> </xa-pool> <timeout> <idle-timeout-minutes>5</idle-timeout-minutes> </timeout> <security> <user-name>...</user-name> <password>...</password> </security> </xa-datasource> | <subsystem xmlns="urn:jboss:domain:transactions:3.0"> <core-environment> <process-id> <uuid/> </process-id> </core-environment> <recovery-environment socket-binding="txn-recovery-environment" status-socket-binding="txn-status-manager"/> <coordinator-environment default-timeout="300" enable-statistics="true"/> <!-- Enabling JTS here seems to solve the problem--> <!--jts/--> </subsystem> | <subsystem xmlns="urn:jboss:domain:jca:4.0"> <archive-validation enabled="true" fail-on-error="true" fail-on-warn="false"/> <bean-validation enabled="true"/> <default-workmanager> <short-running-threads> <core-threads count="50"/> <queue-length count="50"/> <max-threads count="50"/> <keepalive-time time="10" unit="seconds"/> </short-running-threads> <long-running-threads> <core-threads count="50"/> <queue-length count="50"/> <max-threads count="50"/> <keepalive-time time="10" unit="seconds"/> </long-running-threads> </default-workmanager> <cached-connection-manager/> </subsystem> |
---
Here are some log example for the failure case:
// CrmBean aquires a connection from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will be put back to the pool.
13:21:33,761 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 129) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@73e03c
5c[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@594c1ffb connection handles=0 lastReturned=1484745693690 lastValidated=1484745693642 lastCheckedOut=1484745693761 trackByTx=false pool=org.jboss.jca.core
.connectionmanager.pool.strategy.OnePool@2e93c6bc mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@277beead[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@396fea6a[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnectio
n@594c1ffb pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:74c8ec99:587f6b90:2c status: ActionS
tatus.RUNNING >
// PriceBean aquires a connection from the pool and I can see that the "TransactionImple < jca-subordinate" is in the log. This connection will never be put back to the pool
13:21:34,652 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (default task-87) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@7c56eb55[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6128d8d7 connection handles=0 lastReturned=1484745693661 lastValidated=1484745635169 lastCheckedOut=1484745694652 trackByTx=false pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@2e93c6bc mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@277beead[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@d2533cb[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@6128d8d7 pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < jca-subordinate, BasicAction: 0:ffff0af6c016:74c8ec99:587f6b90:36 status: ActionStatus.RUNNING >
EDIT: below is the successful case - not failure
Here are some log example for the success case:
// CrmBean aquires a connection from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will b eput back to the pool.
13:31:11,495 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [] (ServerService Thread Pool -- 78) Got connection from pool tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e7c430
0[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a connection handles=0 lastReturned=1484746271484 lastValidated=1484746269735 lastCheckedOut=1484746271495 trackByTx=false pool=org.jboss.jca.core.
connectionmanager.pool.strategy.OnePool@51760712 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@146717d1[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@137df56c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection
@5400fe1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=null] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionSt
atus.RUNNING >
// PriceBean reuses the connetion that was aquired by the CrmBean from the pool and I can see that the "TransactionImple < ac" is in the log. This connection will be put back to the pool
13:31:11,510 TRACE [org.jboss.jca.core.connectionmanager.pool.strategy.OnePool] [tx-3] (ServerService Thread Pool -- 78) Previous connection tracked by transaction=org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@6e7c4300[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a connection handles=1 lastReturned=1484746271484 lastValidated=1484746269735 lastCheckedOut=1484746271495 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@51760712 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@146717d1[pool=postgres-crm-ds] xaResource=XAResourceWrapperImpl@137df56c[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5400fe1a pad=false overrideRmValue=null productName=PostgreSQL productVersion=9.4.10 jndiName=java:jboss/datasources/postgres-crm-ds] txSync=TransactionSynchronization@1874016840{tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionStatus.RUNNING > wasTrackByTx=true enlisted=true cancel=false}] tx=TransactionImple < ac, BasicAction: 0:ffff0af6c016:45a7bcb8:587f6dd3:81 status: ActionStatus.RUNNING >
13:31:11,510 TRACE [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] [tx-3] (ServerService Thread Pool -- 78) [TxConnectionListener@6e7c4300] registerConnection: org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@51118944 [size=2] ([org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@5cb3a3f3, org.jboss.jca.adapters.jdbc.jdk7.WrappedConnectionJDK7@51118944])
Best regards
Hans-Christian