Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-10962

WFLY14: set-tx-query-timeout broken on xa-datasource

    XMLWordPrintable

Details

    • Bug
    • Resolution: Unresolved
    • Major
    • None
    • 14.0.0.Final
    • JCA
    • None
    • Workaround Exists
    • Hide

      Undefine the set-tx-query-timeout datasource property, or set it to false

      Show
      Undefine the set-tx-query-timeout datasource property, or set it to false

    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:

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

      Followed with tons of:

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

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

      Attachments

        Activity

          People

            smaestri@redhat.com Stefano Maestri
            petr.hostalek@bsc-ideas.com Petr Hostalek (Inactive)
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated: