[jboss-jira] [JBoss JIRA] (WFLY-10962) WFLY14: set-tx-query-timeout broken on xa-datasource

[ https://issues.jboss.org/browse/WFLY-10962?page=com.atlassian.jira.plugin... ] Petr H updated WFLY-10962: -------------------------- Description: In order to test the [WFLY-10621] issue I migrated the domain configuration from WFLY 11 to WFLY 14 and started the domain and process controllers which was successfull. However after starting the 1st app server instance I encountered the following warnings and consequently the application dependent on that particular datasource wasn't working properly: {noformat} 2018-08-31 14:26:00,606 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (myScheduler-1) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@782ae3d8[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@3dabbda5 connection handles=1 lastReturned=1535718358200 lastValidated=1535718345234 lastCheckedOut=1535718358759 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f74fa31 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@7c23cc82[pool=dsName] xaResource=XAResourceWrapperImpl@36ab279f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)3dabbda5 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/dsName] txSync=TransactionSynchronization@1944287995{tx=Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a020b45:-4d9ac9e1:5b8933a1:10 status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]: javax.resource.spi.ResourceAdapterInternalException: Unexpected error at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:664) at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.connectionError(BaseWrapperManagedConnection.java:630) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkException(WrappedConnection.java:1969) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkException(WrappedStatement.java:1436) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:541) ... Caused by: java.lang.NoClassDefFoundError: org/wildfly/transaction/client/ContextTransactionManager at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getTimeLeftBeforeTransactionTimeout(TxConnectionManagerImpl.java:392) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getTimeLeftBeforeTransactionTimeout(WrapperDataSource.java:201) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkConfiguredQueryTimeout(WrappedConnection.java:2043) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkConfiguredQueryTimeout(WrappedStatement.java:1456) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:531) ... 41 more Caused by: java.lang.ClassNotFoundException: org.wildfly.transaction.client.ContextTransactionManager from [Module "org.jboss.ironjacamar.impl" version 1.4.11.Final from local module loader @5e5792a0 (finder: local module finder @26653222 (roots: /opt/wildfly-14.0.0.Final/modules,/opt/wildfly-14.0.0.Final/modules/system/layers/base))] at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:255) at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410) at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398) at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116) ... 46 more {noformat} Followed with tons of: {noformat} 2018-08-31 14:26:00,635 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (ServerService Thread Pool -- 85) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1be6d5f7[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5829c2e1 connection handles=1 lastReturned=1535718360457 lastValidated=1535718334651 lastCheckedOut=1535718360501 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f74fa31 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@7c23cc82[pool=dsName] xaResource=XAResourceWrapperImpl@39069b2f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)5829c2e1 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/dsName] txSync=TransactionSynchronization@1776960750{tx=Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a020b45:-4d9ac9e1:5b8933a1:1a status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]: javax.resource.spi.ResourceAdapterInternalException: Unexpected error at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:664) at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.connectionError(BaseWrapperManagedConnection.java:630) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkException(WrappedConnection.java:1969) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkException(WrappedStatement.java:1436) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:509) ... Caused by: java.lang.NoClassDefFoundError: org/wildfly/transaction/client/ContextTransactionManager at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getTimeLeftBeforeTransactionTimeout(TxConnectionManagerImpl.java:392) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getTimeLeftBeforeTransactionTimeout(WrapperDataSource.java:201) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkConfiguredQueryTimeout(WrappedConnection.java:2043) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkConfiguredQueryTimeout(WrappedStatement.java:1456) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:498) ... 62 more 2018-08-31 14:26:00,775 WARN [com.arjuna.ats.jta] (ServerService Thread Pool -- 85) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a020b45:-4d9ac9e1:5b8933a1:1a, node_name=1, branch_uid=0:ffff0a020b45:-4d9ac9e1:5b8933a1:1e, subordinatenodename=null, eis_name=java:/jdbc/dsName > (XAResourceWrapperImpl@39069b2f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)5829c2e1 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/dsName]) failed with exception code XAException.XAER_RMFAIL: oracle.jdbc.xa.OracleXAException at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1229) at oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:979) at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:357) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196) at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362) at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023) at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002) at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124) at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1370) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:143) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:134) at org.wildfly.transaction.client.LocalTransaction.rollbackAndDissociate(LocalTransaction.java:111) at org.wildfly.transaction.client.ContextTransactionManager.rollback(ContextTransactionManager.java:83) at org.wildfly.transaction.client.LocalUserTransaction.rollback(LocalUserTransaction.java:58) ... Caused by: java.sql.SQLRecoverableException: Closed Connection at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:4220) at oracle.jdbc.driver.T4CXAResource.doTransaction(T4CXAResource.java:756) at oracle.jdbc.driver.T4CXAResource.doRollback(T4CXAResource.java:635) at oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:974) ... 56 more {noformat} (basically on every attempt to use that datasource) Based on the stack trace I deduced this is related to the set-tx-query-timeout=true setting on that datasource (which is xa-datasource) so I removed that for now and the problem disappeared. Notes: 1. Non-XA datasources don't seem to be affected, but they still could be - see the next point. 2. In this particular case this xa-datasource is attempted to be used during the server startup, before the instance is fully up, e.g. before the _WFLYSRV0212: Resuming server_ and _WFLYSRV0026: WildFly Full 14.0.0.Final (WildFly Core 6.0.1.Final) started_ events (for example managed scheduled executors throw _(EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEE0110: Failed to run scheduled task: java.lang.IllegalStateException: WFLYEE0111: Cannot run scheduled task javax.enterprise.concurrent.ManagedExecutors$ManagedRunnable@12caf21c as container is suspended_ at this point). This fact might be somehow related to the issue. However since the 1st failure occurrence the datasource doesn't recover from that. 3. About a month ago I tested the same config (with set-tx-query-timeout in place) at WFLY 13 and there was no such issue, only WFLY 14 is affected. was: In order to test the [WFLY-10621] issue I migrated the domain configuration from WFLY 11 to WFLY 14 and started the domain and process controllers which was successfull. However after starting the 1st app server instance I encountered the following warnings and consequently the application dependent on that particular datasource wasn't working properly: {noformat} 2018-08-31 14:26:00,606 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (myScheduler-1) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@782ae3d8[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@3dabbda5 connection handles=1 lastReturned=1535718358200 lastValidated=1535718345234 lastCheckedOut=1535718358759 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f74fa31 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@7c23cc82[pool=udebsXA] xaResource=XAResourceWrapperImpl@36ab279f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)3dabbda5 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/udebsXA] txSync=TransactionSynchronization@1944287995{tx=Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a020b45:-4d9ac9e1:5b8933a1:10 status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]: javax.resource.spi.ResourceAdapterInternalException: Unexpected error at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:664) at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.connectionError(BaseWrapperManagedConnection.java:630) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkException(WrappedConnection.java:1969) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkException(WrappedStatement.java:1436) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:541) ... Caused by: java.lang.NoClassDefFoundError: org/wildfly/transaction/client/ContextTransactionManager at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getTimeLeftBeforeTransactionTimeout(TxConnectionManagerImpl.java:392) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getTimeLeftBeforeTransactionTimeout(WrapperDataSource.java:201) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkConfiguredQueryTimeout(WrappedConnection.java:2043) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkConfiguredQueryTimeout(WrappedStatement.java:1456) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeUpdate(WrappedPreparedStatement.java:531) ... 41 more Caused by: java.lang.ClassNotFoundException: org.wildfly.transaction.client.ContextTransactionManager from [Module "org.jboss.ironjacamar.impl" version 1.4.11.Final from local module loader @5e5792a0 (finder: local module finder @26653222 (roots: /opt/wildfly-11.0.0.Final/modules,/opt/wildfly-11.0.0.Final/modules/system/layers/base,/opt/BSCPraha/GEMINI/jboss-modules))] at org.jboss.modules.ModuleClassLoader.findClass(ModuleClassLoader.java:255) at org.jboss.modules.ConcurrentClassLoader.performLoadClassUnchecked(ConcurrentClassLoader.java:410) at org.jboss.modules.ConcurrentClassLoader.performLoadClass(ConcurrentClassLoader.java:398) at org.jboss.modules.ConcurrentClassLoader.loadClass(ConcurrentClassLoader.java:116) ... 46 more {noformat} Followed with tons of: {noformat} 2018-08-31 14:26:00,635 WARN [org.jboss.jca.core.connectionmanager.listener.TxConnectionListener] (ServerService Thread Pool -- 85) IJ000305: Connection error occured: org.jboss.jca.core.connectionmanager.listener.TxConnectionListener@1be6d5f7[state=NORMAL managed connection=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@5829c2e1 connection handles=1 lastReturned=1535718360457 lastValidated=1535718334651 lastCheckedOut=1535718360501 trackByTx=true pool=org.jboss.jca.core.connectionmanager.pool.strategy.OnePool@7f74fa31 mcp=SemaphoreConcurrentLinkedQueueManagedConnectionPool@7c23cc82[pool=udebsXA] xaResource=XAResourceWrapperImpl@39069b2f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)5829c2e1 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/udebsXA] txSync=TransactionSynchronization@1776960750{tx=Local transaction (delegate=TransactionImple < ac, BasicAction: 0:ffff0a020b45:-4d9ac9e1:5b8933a1:1a status: ActionStatus.RUNNING >, owner=Local transaction context for provider JBoss JTA transaction provider) wasTrackByTx=true enlisted=true cancel=false}]: javax.resource.spi.ResourceAdapterInternalException: Unexpected error at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.broadcastConnectionError(BaseWrapperManagedConnection.java:664) at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.connectionError(BaseWrapperManagedConnection.java:630) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkException(WrappedConnection.java:1969) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkException(WrappedStatement.java:1436) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:509) ... Caused by: java.lang.NoClassDefFoundError: org/wildfly/transaction/client/ContextTransactionManager at org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl.getTimeLeftBeforeTransactionTimeout(TxConnectionManagerImpl.java:392) at org.jboss.jca.adapters.jdbc.WrapperDataSource.getTimeLeftBeforeTransactionTimeout(WrapperDataSource.java:201) at org.jboss.jca.adapters.jdbc.WrappedConnection.checkConfiguredQueryTimeout(WrappedConnection.java:2043) at org.jboss.jca.adapters.jdbc.WrappedStatement.checkConfiguredQueryTimeout(WrappedStatement.java:1456) at org.jboss.jca.adapters.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:498) ... 62 more 2018-08-31 14:26:00,775 WARN [com.arjuna.ats.jta] (ServerService Thread Pool -- 85) ARJUNA016045: attempted rollback of < formatId=131077, gtrid_length=29, bqual_length=36, tx_uid=0:ffff0a020b45:-4d9ac9e1:5b8933a1:1a, node_name=1, branch_uid=0:ffff0a020b45:-4d9ac9e1:5b8933a1:1e, subordinatenodename=null, eis_name=java:/jdbc/udebsXA > (XAResourceWrapperImpl@39069b2f[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection(a)5829c2e1 pad=false overrideRmValue=false productName=Oracle productVersion=Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production With the Partitioning, Automatic Storage Management, OLAP, Advanced Analytics and Real Application Testing options jndiName=java:/jdbc/udebsXA]) failed with exception code XAException.XAER_RMFAIL: oracle.jdbc.xa.OracleXAException at oracle.jdbc.xa.OracleXAResource.checkError(OracleXAResource.java:1229) at oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:979) at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.rollback(XAManagedConnection.java:357) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.rollback(XAResourceWrapperImpl.java:196) at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:362) at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023) at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002) at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674) at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124) at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1370) at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:143) at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:134) at org.wildfly.transaction.client.LocalTransaction.rollbackAndDissociate(LocalTransaction.java:111) at org.wildfly.transaction.client.ContextTransactionManager.rollback(ContextTransactionManager.java:83) at org.wildfly.transaction.client.LocalUserTransaction.rollback(LocalUserTransaction.java:58) ... Caused by: java.sql.SQLRecoverableException: Closed Connection at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:4220) at oracle.jdbc.driver.T4CXAResource.doTransaction(T4CXAResource.java:756) at oracle.jdbc.driver.T4CXAResource.doRollback(T4CXAResource.java:635) at oracle.jdbc.xa.client.OracleXAResource.rollback(OracleXAResource.java:974) ... 56 more {noformat} (basically on every attempt to use that datasource) Based on the stack trace I deduced this is related to the set-tx-query-timeout=true setting on that datasource (which is xa-datasource) so I removed that for now and the problem disappeared. Notes: 1. Non-XA datasources don't seem to be affected, but they still could be - see the next point. 2. In this particular case this xa-datasource is attempted to be used during the server startup, before the instance is fully up, e.g. before the _WFLYSRV0212: Resuming server_ and _WFLYSRV0026: WildFly Full 14.0.0.Final (WildFly Core 6.0.1.Final) started_ events (for example managed scheduled executors throw _(EE-ManagedScheduledExecutorService-default-Thread-1) WFLYEE0110: Failed to run scheduled task: java.lang.IllegalStateException: WFLYEE0111: Cannot run scheduled task javax.enterprise.concurrent.ManagedExecutors$ManagedRunnable@12caf21c as container is suspended_ at this point). This fact might be somehow related to the issue. However since the 1st failure occurrence the datasource doesn't recover from that. 3. About a month ago I tested the same config (with set-tx-query-timeout in place) at WFLY 13 and there was no such issue, only WFLY 14 is affected. -- This message was sent by Atlassian JIRA (v7.5.0#75005)