[jboss-jira] [JBoss JIRA] (AG-94) "Closing connection in incorrect state" log spam
Rich DiCroce (JIRA)
issues at jboss.org
Mon Sep 24 12:28:00 EDT 2018
[ https://issues.jboss.org/browse/AG-94?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13637636#comment-13637636 ]
Rich DiCroce commented on AG-94:
--------------------------------
Evidence points to this being a race condition. It seems to happen more when the application is busier (i.e. using the database more).
> "Closing connection in incorrect state" log spam
> ------------------------------------------------
>
> Key: AG-94
> URL: https://issues.jboss.org/browse/AG-94
> Project: Agroal
> Issue Type: Bug
> Components: pool
> Affects Versions: 1.1
> Environment: WildFly 14.0.0.Final
> Reporter: Rich DiCroce
> Assignee: Luis Barreiro
>
> My WildFly application gets a lot of log spam like this:
> {code}
> 13:45:39,741 WARN [io.agroal.pool] (Agroal_17017539771) WFLYAG0601: DLS_DS: Closing connection in incorrect state CHECKED_IN
> {code}
> In trying to debug it, I found a potential cause. ConnectionPool line 251 comments that "handler not in CHECKED_OUT implies FLUSH" but that appears to be a bad assumption. For the stack trace below (obtained by setting a breakpoint at ConnectionPool line 346), the state was CHECKED_IN.
> I also filed WFLY-11037, but nobody has looked at it and this seems more like an Agroal bug at this point.
> {code}
> "default task-2" #149 prio=5 os_prio=0 tid=0x000000002315c800 nid=0x10498 at breakpoint[0x0000000035c5b000]
> java.lang.Thread.State: RUNNABLE
> at io.agroal.pool.ConnectionPool$FlushTask.<init>(ConnectionPool.java:346)
> at io.agroal.pool.ConnectionPool.returnConnection(ConnectionPool.java:252)
> at io.agroal.pool.ConnectionHandler.returnConnection(ConnectionHandler.java:68)
> at io.agroal.pool.wrapper.ConnectionWrapper.close(ConnectionWrapper.java:186)
> at io.agroal.narayana.NarayanaTransactionIntegration$InterposedSynchronization.afterCompletion(NarayanaTransactionIntegration.java:127)
> at org.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization$$Lambda$711/1634329013.accept(Unknown Source)
> at org.wildfly.transaction.client.AbstractTransaction.performConsumer(AbstractTransaction.java:223)
> at org.wildfly.transaction.client.AbstractTransaction$AssociatingSynchronization.afterCompletion(AbstractTransaction.java:306)
> at com.arjuna.ats.internal.jta.resources.arjunacore.SynchronizationImple.afterCompletion(SynchronizationImple.java:96)
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.afterCompletion(TwoPhaseCoordinator.java:545)
> - locked <0x00000000f6201298> (a java.lang.Object)
> at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.end(TwoPhaseCoordinator.java:101)
> at com.arjuna.ats.arjuna.AtomicAction.commit(AtomicAction.java:162)
> at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1288)
> at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)
> at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:89)
> at org.wildfly.transaction.client.LocalTransaction.commitAndDissociate(LocalTransaction.java:77)
> at org.wildfly.transaction.client.ContextTransactionManager.commit(ContextTransactionManager.java:71)
> at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.endTransaction(TransactionalInterceptorBase.java:232)
> at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.invokeInOurTx(TransactionalInterceptorBase.java:178)
> at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.doIntercept(TransactionalInterceptorRequired.java:53)
> at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorBase.intercept(TransactionalInterceptorBase.java:88)
> at com.arjuna.ats.jta.cdi.transactional.TransactionalInterceptorRequired.intercept(TransactionalInterceptorRequired.java:47)
> at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
> at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
> at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
> at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
> at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
> at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
> at com.sg.song.dls.config.unified.UnifiedConfig$Proxy$_$$_WeldSubclass.changeConfigValues(Unknown Source)
> at com.sg.song.dls.config.unified.UnifiedConfig$Proxy$_$$_WeldClientProxy.changeConfigValues(Unknown Source)
> at com.sg.song.dls.rest.ui.config.UIUnifiedConfigService.changeSettings(UIUnifiedConfigService.java:45)
> at com.sg.song.dls.rest.ui.config.UIUnifiedConfigService$Proxy$_$$_WeldClientProxy.changeSettings(Unknown Source)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:140)
> at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:509)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:399)
> at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$0(ResourceMethodInvoker.java:363)
> at org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$765/920149366.get(Unknown Source)
> at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
> - locked <0x00000000f61fac30> (a org.jboss.resteasy.core.interception.PostMatchContainerRequestContext)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:365)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:337)
> at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:310)
> at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:443)
> at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:233)
> at org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$763/354670022.run(Unknown Source)
> at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:139)
> at org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$764/1839877196.get(Unknown Source)
> at org.jboss.resteasy.core.interception.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:358)
> - locked <0x00000000f61f9880> (a org.jboss.resteasy.core.interception.PreMatchContainerRequestContext)
> at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:142)
> at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:219)
> at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:227)
> at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
> at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:791)
> 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.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
> at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
> 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.security.SecurityContextThreadSetupAction$$Lambda$677/604722672.call(Unknown Source)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$678/2109666898.call(Unknown Source)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$678/2109666898.call(Unknown Source)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$678/2109666898.call(Unknown Source)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$678/2109666898.call(Unknown Source)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1502)
> at org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction$$Lambda$678/2109666898.call(Unknown Source)
> 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)
> {code}
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the jboss-jira
mailing list