[jboss-jira] [JBoss JIRA] (WFLY-12718) Clustering: replicated-cache sampling errors

Radoslav Husar (Jira) issues at jboss.org
Tue Oct 29 13:16:00 EDT 2019 

    [ https://issues.jboss.org/browse/WFLY-12718?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13805738#comment-13805738 ] 

Radoslav Husar commented on WFLY-12718:
---------------------------------------

The exceptions in the test log are timeouts.

{noformat}
2019-10-28 18:48:01,307 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor] (timeout-thread--p12-t1) ISPN000136: Error executing command PrepareCommand on Cache 'clusterbench-ee8.ear.clusterbench-ee8-web.war', writing keys [SessionAccessMetaDataKey(SSpenckNGHL1Y20-8vGPxHRvN-ASy2Xo19q09mJi), SessionCreationMetaDataKey(SSpenckNGHL1Y20-8vGPxHRvN-ASy2Xo19q09mJi)]: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 228131 from wildfly2
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.impl.MultiTargetRequest.onTimeout(MultiTargetRequest.java:167)
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87)
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:834)

2019-10-28 18:48:01,305 ERROR [org.infinispan.transaction.impl.TransactionCoordinator] (default task-155) ISPN000097: Error while processing a prepare in a single-phase transaction: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 228130 from wildfly2
	at org.infinispan at 9.4.16.Final//org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:259)
	at org.infinispan at 9.4.16.Final//org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:156)
	at org.infinispan at 9.4.16.Final//org.infinispan.transaction.impl.TransactionTable.afterCompletion(TransactionTable.java:861)
	at org.infinispan at 9.4.16.Final//org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:33)
	at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.notifyAfterCompletion(TransactionImpl.java:506)
	at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:338)
	at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110)
	at org.wildfly.clustering.ee.cache at 18.0.0.Final//org.wildfly.clustering.ee.cache.tx.TransactionalBatch.close(TransactionalBatch.java:98)
	at org.wildfly.clustering.web.undertow at 18.0.0.Final//org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:87)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:950)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:621)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:328)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
	at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
	at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
	at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
	at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
	at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
	at io.undertow.core at 2.0.26.Final//io.undertow.server.Connectors.executeRootHandler(Connectors.java:376)
	at io.undertow.core at 2.0.26.Final//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
	at org.jboss.threads at 2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
	at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
	at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
	at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1363)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 228130 from wildfly2
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.impl.MultiTargetRequest.onTimeout(MultiTargetRequest.java:167)
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:87)
	at org.infinispan at 9.4.16.Final//org.infinispan.remoting.transport.AbstractRequest.call(AbstractRequest.java:22)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more
	Suppressed: org.infinispan.util.logging.TraceException
		at org.infinispan at 9.4.16.Final//org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:41)
		at org.infinispan at 9.4.16.Final//org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:250)
		at org.infinispan at 9.4.16.Final//org.infinispan.transaction.impl.TransactionCoordinator.commit(TransactionCoordinator.java:156)
		at org.infinispan at 9.4.16.Final//org.infinispan.transaction.impl.TransactionTable.afterCompletion(TransactionTable.java:861)
		at org.infinispan at 9.4.16.Final//org.infinispan.transaction.synchronization.SynchronizationAdapter.afterCompletion(SynchronizationAdapter.java:33)
		at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.notifyAfterCompletion(TransactionImpl.java:506)
		at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:338)
		at org.infinispan.commons at 9.4.16.Final//org.infinispan.commons.tx.TransactionImpl.commit(TransactionImpl.java:110)
		at org.wildfly.clustering.ee.cache at 18.0.0.Final//org.wildfly.clustering.ee.cache.tx.TransactionalBatch.close(TransactionalBatch.java:98)
		at org.wildfly.clustering.web.undertow at 18.0.0.Final//org.wildfly.clustering.web.undertow.session.DistributableSession.requestDone(DistributableSession.java:87)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.spec.ServletContextImpl.updateSessionAccessTime(ServletContextImpl.java:950)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.spec.HttpServletResponseImpl.responseDone(HttpServletResponseImpl.java:621)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:328)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
		at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.security.SecurityContextThreadSetupAction.lambda$create$0(SecurityContextThreadSetupAction.java:105)
		at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
		at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
		at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
		at org.wildfly.extension.undertow at 18.0.0.Final//org.wildfly.extension.undertow.deployment.UndertowDeploymentInfoService$UndertowThreadSetupAction.lambda$create$0(UndertowDeploymentInfoService.java:1504)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
		at io.undertow.servlet at 2.0.26.Final//io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
		at io.undertow.core at 2.0.26.Final//io.undertow.server.Connectors.executeRootHandler(Connectors.java:376)
		at io.undertow.core at 2.0.26.Final//io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
		at org.jboss.threads at 2.3.3.Final//org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
		at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:1982)
		at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1486)
		at org.jboss.threads at 2.3.3.Final//org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1363)
		... 1 more
{noformat}

> Clustering: replicated-cache sampling errors
> --------------------------------------------
>
>                 Key: WFLY-12718
>                 URL: https://issues.jboss.org/browse/WFLY-12718
>             Project: WildFly
>          Issue Type: Bug
>          Components: Clustering
>    Affects Versions: 18.0.0.Final
>            Reporter: Tommasso Borgato
>            Assignee: Paul Ferraro
>            Priority: Blocker
>
> The issue is about replicated-cache in fail-over tests.
> WildFly is started in clustered mode using a replicated cache for replicating HTTP session data across cluster nodes; all 4 nodes in the cluster are initialized with the following cli script:
> {noformat}
> embed-server --server-config=standalone-ha.xml
> /subsystem=jgroups/channel=ee:write-attribute(name=stack,value=tcp)
> /subsystem=infinispan/cache-container=web/replicated-cache=testRepl:add()
> /subsystem=infinispan/cache-container=web/replicated-cache=testRepl/component=locking:write-attribute(name=isolation, value=REPEATABLE_READ)
> /subsystem=infinispan/cache-container=web/replicated-cache=testRepl/component=transaction:write-attribute(name=mode, value=BATCH)
> /subsystem=infinispan/cache-container=web/replicated-cache=testRepl/store=file:add()
> /subsystem=infinispan/cache-container=web:write-attribute(name=default-cache, value=testRepl)
> {noformat}
> The test is run with wildfly-18.​0.0.Final.zip;
> The same tests run with version wildfly-17.​0.1.Final.zip do not have any problem;
> hence this looks like a regression;
> As usual, we test that the serial value stored in the scattered cache is incremented at every call: when this is not true, we say we have a sampling error;
> Here are the runs that exhibit this issue: 
> - **22.82% Fail Rate with WildFly-18 ** [eap-7.x-clustering-http-session-shutdown-repl#23|https://eap-qe-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/EAP7/view/EAP7-Clustering/view/EAP7-Clustering-HTTP-Session/job/eap-7.x-clustering-http-session-shutdown-repl/23/artifact/report/jm/html/index.html]
> - **0% Fail Rate with WildFly-17 ** [eap-7.x-clustering-http-session-shutdown-repl#24|https://eap-qe-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/EAP7/view/EAP7-Clustering/view/EAP7-Clustering-HTTP-Session/job/eap-7.x-clustering-http-session-shutdown-repl/24/artifact/report/jm/html/index.html]
> We also repeated the tests to make sure it can be reproduced:
> - **22.75% Fail rate with WildFly-18 ** [eap-7.x-clustering-http-session-shutdown-repl#26|https://eap-qe-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/EAP7/view/EAP7-Clustering/view/EAP7-Clustering-HTTP-Session/job/eap-7.x-clustering-http-session-shutdown-repl/26/artifact/report/jm/html/index.html] 
> - **0% Fail Rate with WildFly-17 ** [eap-7.x-clustering-http-session-shutdown-repl#25|https://eap-qe-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/EAP7/view/EAP7-Clustering/view/EAP7-Clustering-HTTP-Session/job/eap-7.x-clustering-http-session-shutdown-repl/25/artifact/report/jm/html/index.html]



--
This message was sent by Atlassian Jira
(v7.13.8#713008)

More information about the jboss-jira mailing list