Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-13230

TimeoutException during failover shutdown-dist-sync scenario

XMLWordPrintable

      We saw this error on server during failover scenario ejb-ejbremote-shutdown-dist-sync-tcpStack (1 occurence).

      Shortly after cluster-wide rebalance finished and before new cluster view was received the org.infinispan.util.concurrent.TimeoutException was logged.

      Server log stacktrace:

      15:35:14,326 ERROR [org.jboss.as.ejb3.invocation] (default task-26) WFLYEJB0034: EJB Invocation failed on component RemoteStatefulSBImpl for method public abstract int org.jboss.test.clusterbench.common.ejb.CommonStatefulSB.getSerialAndIncrement(): javax.ejb.EJBException: org.infinispan.util.concurrent.TimeoutException: Replication timeout
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleExceptionInOurTx(CMTTxInterceptor.java:188)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:277)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:332)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:509)
[JBossINF] 	at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73)
[JBossINF] 	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:89)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:57)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:438)
[JBossINF] 	at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609)
[JBossINF] 	at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:422)
[JBossINF] 	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
[JBossINF] 	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
[JBossINF] 	at org.wildfly.security.auth.server.SecurityIdentity.runAsFunctionEx(SecurityIdentity.java:380)
[JBossINF] 	at org.jboss.as.ejb3.remote.AssociationImpl.invokeWithIdentity(AssociationImpl.java:524)
[JBossINF] 	at org.jboss.as.ejb3.remote.AssociationImpl.invokeMethod(AssociationImpl.java:519)
[JBossINF] 	at org.jboss.as.ejb3.remote.AssociationImpl.lambda$receiveInvocationRequest$0(AssociationImpl.java:193)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[JBossINF] 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[JBossINF] 	at java.lang.Thread.run(Thread.java:748)
[JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: Replication timeout
[JBossINF] 	at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$1(JGroupsTransport.java:639)
[JBossINF] 	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602)
[JBossINF] 	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
[JBossINF] 	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
[JBossINF] 	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
[JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:61)
[JBossINF] 	at org.infinispan.remoting.transport.jgroups.RspListFuture.call(RspListFuture.java:16)
[JBossINF] 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
[JBossINF] 	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
[JBossINF] 	... 3 more
[JBossINF] 	Suppressed: org.infinispan.remoting.RpcException: Not accepted: SuccessfulResponse{responseValue=true} 
[JBossINF] 		at org.infinispan.remoting.transport.jgroups.JGroupsTransport.addSuppressedExceptions(JGroupsTransport.java:694)
[JBossINF] 		... 13 more
[JBossINF] 
[JBossINF] �15:36:13,285 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (thread-2) ISPN000094: Received new cluster view for channel server: [perf21|5] (4) [perf21, perf20, perf19, perf18]
[JBossINF] �15:36:13,286 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (thread-2) ISPN000094: Received new cluster view for channel web: [perf21|5] (4) [perf21, perf20, perf19, perf18]
[JBossINF] �15:36:13,287 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (thread-2) ISPN000094: Received new cluster view for channel hibernate: [perf21|5] (4) [perf21, perf20, perf19, perf18]
[JBossINF] �15:36:13,287 INFO  [org.infinispan.remoting.transport.jgroups.JGroupsTransport] (thread-2) ISPN000094: Received new cluster view for channel ejb: [perf21|5] (4) [perf21, perf20, perf19, perf18]

      Client was also affected, there was an error logged at the same time:

      2017/09/20 15:35:14:432 EDT [ERROR][Runner - 315] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error getting response. <javax.ejb.EJBException: org.infinispan.util.concurrent.TimeoutException: Replication timeout>

      followed by two WARN messages:

      2017/09/20 15:35:14:432 EDT [WARN ][Runner - 315] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 315.>
        
2017/09/20 15:35:14:432 EDT [WARN ][Runner - 315] SFCORE_LOG - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 315.>
        org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 315.
	at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImpl.java:113)
	at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52)
	at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:108)
	at java.lang.Thread.run(Thread.java:748)
Caused by: javax.ejb.EJBException: org.infinispan.util.concurrent.TimeoutException: Replication timeout
	at org.jboss.as.ejb3.remote.AssociationImpl.lambda$receiveInvocationRequest$0(AssociationImpl.java:218)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	... 1 more

      One of the nodes (perf18) was shutdown shortly before:

      2017/09/20 15:35:01:680 EDT [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Node 0 (perf18) is down.
2017/09/20 15:35:01:681 EDT [INFO ][TestController] HOST perf17.mw.lab.eng.bos.redhat.com:rootProcess:c - Cluster state: [DOWN, UP, UP, UP].

      Link to server log:
      http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-ejb-ejbremote-shutdown-dist-sync-tcpStack/28/console-perf21/

      Link to client log:
      http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-ejb-ejbremote-shutdown-dist-sync-tcpStack/28/console-perf17/

              rpelisse@redhat.com Romain Pelisse
              dcihak@redhat.com Daniel Cihak
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Created:
                Updated:
                Resolved: