Possibly unneccessary logging on XA endAssociation with DB2
I'm running wildfly 13 (narayana 5.8.1.Final) with a DB2 database using XA datasource.
Whenever I do setRollbackOnly(true) in a CMT ejb I get WARN logging (full log at bottom of post).
2018-09-27 16:14:54,439 WARN [com.arjuna.ats.jta:1104 doEnd] (default task-1) ARJUNA016129: Could not end XA resource XAResourceWrapperImpl@61bf3c2d[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4f2c58cc pad=false overrideRmValue=false productName=DB2/LINUXX8664 productVersion=SQL11010 jndiName=java:/iipax.db]: com.ibm.db2.jcc.am.XaException: [jcc][t4][10401][12066][3.72.44] XA exception: XA_RBROLLBACK ERRORCODE=-4228, SQLSTATE=null
Although it seems that the rollback works as expected anyway.
I tracked the log-call down to com.arjuna.ats.internal.jta.transaction.jts.TransactionImple.doEnd(Xid, XAResource, int, int)
This method was added in the commit fcfb851072ea28c80902710e1179fbb9f62b3ca3 where the logic moved from XaResourceRecord to TransactionImple, at the same time the logging was introduced as far as I can tell.
So my question is if this logging really is unneccessary in this case, or if something is actually wrong with my application or configuration.
My datasource configuration:
<xa-datasource jndi-name="java:/iipax.db" pool-name="iipax.db">
<xa-datasource-property name="DriverType">4</xa-datasource-property>
<xa-datasource-property name="PortNumber">3708</xa-datasource-property>
<xa-datasource-property name="DatabaseName">*****</xa-datasource-property>
<xa-datasource-property name="ServerName">*****</xa-datasource-property>
<xa-datasource-property name="resultSetHoldability">1</xa-datasource-property>
<xa-datasource-property name="downgradeHoldCursorsUnderXa">true</xa-datasource-property>
<driver>db2</driver>
<xa-pool>
<is-same-rm-override>false</is-same-rm-override>
<min-pool-size>10</min-pool-size>
<max-pool-size>300</max-pool-size>
</xa-pool>
<security>
<user-name>iipax</user-name>
<password>${VAULT::vb::database_user_password::1}</password>
</security>
<validation>
<valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.db2.DB2ValidConnectionChecker"/>
<validate-on-match>true</validate-on-match>
<background-validation>false</background-validation>
<exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.db2.DB2ExceptionSorter"/>
</validation>
<timeout>
<blocking-timeout-millis>300000</blocking-timeout-millis>
</timeout>
</xa-datasource>
The complete stacktrace
2018-09-27 16:14:54,439 WARN [com.arjuna.ats.jta:1104 doEnd] (default task-1) ARJUNA016129: Could not end XA resource XAResourceWrapperImpl@61bf3c2d[xaResource=org.jboss.jca.adapters.jdbc.xa.XAManagedConnection@4f2c58cc pad=false overrideRmValue=false productName=DB2/LINUXX8664 productVersion=SQL11010 jndiName=java:/iipax.db]: com.ibm.db2.jcc.am.XaException: [jcc][t4][10401][12066][3.72.44] XA exception: XA_RBROLLBACK ERRORCODE=-4228, SQLSTATE=null at com.ibm.db2.jcc.am.b1.c(b1.java:565) at com.ibm.db2.jcc.am.b1.c(b1.java:594) at com.ibm.db2.jcc.t4.a4.a(a4.java:2105) at com.ibm.db2.jcc.t4.a4.end(a4.java:680) at org.jboss.jca.adapters.jdbc.xa.XAManagedConnection.end(XAManagedConnection.java:299) at org.jboss.jca.core.tx.jbossts.XAResourceWrapperImpl.end(XAResourceWrapperImpl.java:118) at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1090) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1061) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1286) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3023) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:3002) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1674) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:124) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1372) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:143) [narayana-jts-idlj-5.8.1.Final.jar:5.8.1.Final (revision: f86d4)] at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:134) at org.wildfly.transaction.client.LocalTransaction.rollbackAndDissociate(LocalTransaction.java:111) [wildfly-transaction-client-1.1.2.Final.jar:1.1.2.Final] at org.wildfly.transaction.client.ContextTransactionManager.rollback(ContextTransactionManager.java:83) [wildfly-transaction-client-1.1.2.Final.jar:1.1.2.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:90) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:122) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:256) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:362) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:144) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509) at org.jboss.weld.module.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:81) [weld-ejb-3.0.4.Final.jar:3.0.4.Final] at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.AuthorizationInterceptor.processInvocation(AuthorizationInterceptor.java:138) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.EjbExceptionTransformingInterceptorFactories$2.processInvocation(EjbExceptionTransformingInterceptorFactories.java:108) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54) [wildfly-ejb3-13.0.0.Final.jar:13.0.0.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438) at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:619) [wildfly-elytron-1.3.3.Final.jar:1.3.3.Final] at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57) at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422) at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53) at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198) at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:185) at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:81) at iipax.service.casekernel.client.iface.CaseFacadeLocal$$$view95.closeCase(Unknown Source) [casekernel.jar:] at iipax.service.casekernel.test.TestConfigUtil.removeTestTypesAndObjects(TestConfigUtil.java:276) at iipax.service.casekernel.test.TestConfigUtil.setUpTestSecurityAndConfig(TestConfigUtil.java:178) at iipax.service.casekernel.test.AbstractCaseEnterpriseTest.eeSetUpNoTran(AbstractCaseEnterpriseTest.java:96) at iipax.embedded.junit.EnterpriseTest.setUp(EnterpriseTest.java:61) at junit.framework.TestCase.runBare(TestCase.java:125) at org.apache.cactus.internal.AbstractCactusTestCase.runBareServer(AbstractCactusTestCase.java:155) at org.apache.cactus.internal.server.AbstractWebTestCaller.doTest(AbstractWebTestCaller.java:120) at org.apache.cactus.internal.server.AbstractWebTestController.handleRequest_aroundBody0(AbstractWebTestController.java:94) at org.apache.cactus.internal.server.AbstractWebTestController.handleRequest_aroundBody1$advice(AbstractWebTestController.java:225) at org.apache.cactus.internal.server.AbstractWebTestController.handleRequest(AbstractWebTestController.java:1) at org.apache.cactus.server.ServletTestRedirector.doPost_aroundBody2(ServletTestRedirector.java:102) at org.apache.cactus.server.ServletTestRedirector.doPost_aroundBody3$advice(ServletTestRedirector.java:225) at org.apache.cactus.server.ServletTestRedirector.doPost(ServletTestRedirector.java:1) at org.apache.cactus.server.ServletTestRedirector.doGet_aroundBody0(ServletTestRedirector.java:73) at org.apache.cactus.server.ServletTestRedirector.doGet_aroundBody1$advice(ServletTestRedirector.java:225) at org.apache.cactus.server.ServletTestRedirector.doGet(ServletTestRedirector.java:1) at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) [jboss-servlet-api_3.1_spec-1.0.2.Final.jar:1.0.2.Final] at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) [jboss-servlet-api_3.1_spec-1.0.2.Final.jar:1.0.2.Final] at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74) at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68) at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132) at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.security.handlers.AuthenticationConstraintHandler.handleRequest(AuthenticationConstraintHandler.java:53) at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) at io.undertow.servlet.handlers.security.ServletSecurityConstraintHandler.handleRequest(ServletSecurityConstraintHandler.java:59) at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50) at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at org.wildfly.extension.undertow.deployment.GlobalRequestControllerHandler.handleRequest(GlobalRequestControllerHandler.java:68) at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:292) at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:138) at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135) at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48) at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43) at org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1514) at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:272) at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:104) at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360) at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830) at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35) at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1985) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1487) at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1378) at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_181]
