Loading...

Type: Bug
Resolution: Done
Priority: Major
Fix Version/s: 7.1.0.CR3
Affects Version/s: 7.1.0.DR15, 7.1.0.DR16, 7.1.0.DR17, 7.1.0.DR18, 7.1.0.DR19
Component/s: Clustering
Labels:
None

CDW devel_ack:
CDW docs_ack:
CDW pm_ack:
CDW qa_ack:
CDW release:
Target Release:

7.backlog.GA

SFDC Cases Counter:
SFDC Cases Open:
SFDC Cases Links:

We saw this error on server during failover test.

Scenario ejb-2clusters-ejbremote-shutdown-repl-async is affected. This scenario tests failover of remote invocations of both stateful and stateless clustered EJBs where the EJB client is both a standalone program and a cluster.

Error occurs approx. 1 second after server started and is preceded by another error:

02:34:42,591 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (default task-47) ISPN000136: Error executing command GetKeyValueCommand, writing keys []: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UUIDSessionID [825be03c-3387-48b8-b596-c493add55785] and requestor GlobalTransaction:<perf18>:32:local. Lock is held by GlobalTransaction:<perf18>:24:local

Server log stacktrace:

02:34:42,596 ERROR [org.jboss.as.ejb3.invocation] (default task-47) WFLYEJB0034: EJB Invocation failed on component RemoteStatefulSBImpl for method public abstract int org.jboss.test.clusterbench.common.ejb.CommonStatefulSB.getSerialAndIncrement(): javax.ejb.EJBTransactionRolledbackException: ISPN000299: Unable to acquire lock after 15 seconds for key UUIDSessionID [825be03c-3387-48b8-b596-c493add55785] and requestor GlobalTransaction:<perf18>:32:local. Lock is held by GlobalTransaction:<perf18>:24:local
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.handleInCallerTx(CMTTxInterceptor.java:160)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:257)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:334)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:327)
[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:240)
[JBossINF] 	at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:84)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:57)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:256)
[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:240)
[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:457)
[JBossINF] 	at org.jboss.as.ejb3.remote.AssociationImpl.invokeMethod(AssociationImpl.java:452)
[JBossINF] 	at org.jboss.as.ejb3.remote.AssociationImpl.lambda$receiveInvocationRequest$0(AssociationImpl.java:164)
[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:745)
[JBossINF] Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after 15 seconds for key UUIDSessionID [825be03c-3387-48b8-b596-c493add55785] and requestor GlobalTransaction:<perf18>:32:local. Lock is held by GlobalTransaction:<perf18>:24:local
[JBossINF] 	at org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.lock(DefaultLockManager.java:238)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAndRecord(AbstractLockingInterceptor.java:193)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockKey(AbstractTxLockingInterceptor.java:193)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockOrRegisterBackupLock(AbstractTxLockingInterceptor.java:116)
[JBossINF] 	at org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataReadCommand(PessimisticLockingInterceptor.java:71)
[JBossINF] 	at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:80)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.enlistReadAndInvokeNext(TxInterceptor.java:346)
[JBossINF] 	at org.infinispan.interceptors.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:331)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitReadCommand(StateTransferInterceptor.java:177)
[JBossINF] 	at org.infinispan.statetransfer.StateTransferInterceptor.visitGetKeyValueCommand(StateTransferInterceptor.java:154)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:110)
[JBossINF] 	at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:79)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:99)
[JBossINF] 	at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:113)
[JBossINF] 	at org.infinispan.commands.AbstractVisitor.visitGetKeyValueCommand(AbstractVisitor.java:85)
[JBossINF] 	at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:43)
[JBossINF] 	at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:335)
[JBossINF] 	at org.infinispan.cache.impl.CacheImpl.get(CacheImpl.java:414)
[JBossINF] 	at org.infinispan.cache.impl.DecoratedCache.get(DecoratedCache.java:443)
[JBossINF] 	at org.infinispan.cache.impl.AbstractDelegatingCache.get(AbstractDelegatingCache.java:287)
[JBossINF] 	at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:88)
[JBossINF] 	at org.wildfly.clustering.ejb.infinispan.bean.InfinispanBeanFactory.findValue(InfinispanBeanFactory.java:50)
[JBossINF] 	at org.wildfly.clustering.ejb.infinispan.InfinispanBeanManager.findBean(InfinispanBeanManager.java:267)
[JBossINF] 	at org.jboss.as.ejb3.cache.distributable.DistributableCache.get(DistributableCache.java:109)
[JBossINF] 	at org.jboss.as.ejb3.component.stateful.StatefulComponentInstanceInterceptor.processInvocation(StatefulComponentInstanceInterceptor.java:52)
[JBossINF] 	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
[JBossINF] 	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInCallerTx(CMTTxInterceptor.java:255)
[JBossINF] 	... 42 more

There is an error logged on client during the whole test duration. Separate ticket was created for this exception: ~~JBEAP-10751~~.
Client log stacktrace:

2017/05/02 02:34:42:641 EDT [WARN ][Runner - 3] SFCORE_LOG - Error sampling data:  <org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 3.>
        org.jboss.smartfrog.loaddriver.RequestProcessingException: Could not get valid response. Runner: 3.
	at org.jboss.smartfrog.clustering.ejb3.StatefulSBProcessorFactoryImpl$EJB3RequestProcessor.processRequest(StatefulSBProcessorFactoryImpl.java:114)
	at org.jboss.smartfrog.loaddriver.CompoundRequestProcessorFactoryImpl$CompoundRequestProcessor.processRequest(CompoundRequestProcessorFactoryImpl.java:52)
	at org.jboss.smartfrog.loaddriver.Runner.run(Runner.java:103)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.SecurityException: WFTXN0013: The peer threw a SecurityException; see peer logs for more information
	at org.wildfly.transaction.client.provider.remoting.TransactionClientChannel.setRollbackOnly(TransactionClientChannel.java:178)
	at org.wildfly.transaction.client.provider.remoting.RemotingRemoteTransactionPeer$1.end(RemotingRemoteTransactionPeer.java:158)
	at org.wildfly.transaction.client.SubordinateXAResource.end(SubordinateXAResource.java:130)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.doEnd(TransactionImple.java:1089)
	at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.endAssociation(TransactionImple.java:1060)
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.endAssociation(XAResourceRecord.java:1287)
	at com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord.topLevelAbort(XAResourceRecord.java:313)
	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:1371)
	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:102)
	at org.wildfly.transaction.client.ContextTransactionManager.rollback(ContextTransactionManager.java:83)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:94)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInOurTx(CMTTxInterceptor.java:279)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.required(CMTTxInterceptor.java:332)
	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:240)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:327)
	at org.jboss.weld.ejb.AbstractEJBRequestScopeActivationInterceptor.aroundInvoke(AbstractEJBRequestScopeActivationInterceptor.java:73)
	at org.jboss.as.weld.ejb.EjbRequestScopeActivationInterceptor.processInvocation(EjbRequestScopeActivationInterceptor.java:89)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.remote.EJBRemoteTransactionPropagatingInterceptor.processInvocation(EJBRemoteTransactionPropagatingInterceptor.java:89)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.component.invocationmetrics.WaitTimeInterceptor.processInvocation(WaitTimeInterceptor.java:47)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.security.SecurityContextInterceptor.processInvocation(SecurityContextInterceptor.java:100)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.deployment.processors.StartupAwaitInterceptor.processInvocation(StartupAwaitInterceptor.java:22)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:64)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.deployment.processors.EjbSuspendInterceptor.processInvocation(EjbSuspendInterceptor.java:57)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:67)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:54)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.invocation.ContextClassLoaderInterceptor.processInvocation(ContextClassLoaderInterceptor.java:60)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.invocation.InterceptorContext.run(InterceptorContext.java:256)
	at org.wildfly.security.manager.WildFlySecurityManager.doChecked(WildFlySecurityManager.java:609)
	at org.jboss.invocation.AccessCheckingInterceptor.processInvocation(AccessCheckingInterceptor.java:57)
	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:240)
	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:53)
	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:198)
	at org.wildfly.security.auth.server.SecurityIdentity.runAsFunctionEx(SecurityIdentity.java:380)
	at org.jboss.as.ejb3.remote.AssociationImpl.invokeWithIdentity(AssociationImpl.java:457)
	at org.jboss.as.ejb3.remote.AssociationImpl.invokeMethod(AssociationImpl.java:452)
	at org.jboss.as.ejb3.remote.AssociationImpl.lambda$receiveInvocationRequest$0(AssociationImpl.java:164)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	... 1 more
Caused by: Remote exception java.lang.SecurityException: WFTXN0088: User anonymous does not have permission ("org.wildfly.transaction.client.RemoteTransactionPermission" "")
	at org.wildfly.transaction.client.provider.remoting.TransactionServerChannel.getSecurityIdentity(TransactionServerChannel.java:729)
	at org.wildfly.transaction.client.provider.remoting.TransactionServerChannel.handleXaTxnRollbackOnly(TransactionServerChannel.java:386)
	at org.wildfly.transaction.client.provider.remoting.TransactionServerChannel$ReceiverImpl.handleMessage(TransactionServerChannel.java:132)
	at org.jboss.remoting3.remote.RemoteConnectionChannel.lambda$handleMessageData$3(RemoteConnectionChannel.java:434)
	at org.jboss.remoting3.EndpointImpl$TrackingExecutor.lambda$execute$0(EndpointImpl.java:891)
	... 3 more

Link to server log:
http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-ejb-2clusters-ejbremote-shutdown-repl-async/16/console-perf18/

Link to client log:
http://jenkins.hosts.mwqe.eng.bos.redhat.com/hudson/job/perflab_eap-7x-failover-ejb-2clusters-ejbremote-shutdown-repl-async/16/console-perf17/

relates to

JBEAP-13963 [GSS](7.1.z) Server-server EJB transactional invocation rolls back if stateful bean is used and JBOSS-LOCAL-USER auth is not possible

Closed

JBEAP-15738 [GSS](7.2.z) Server-server EJB transactional invocation rolls back if stateful bean is used and JBOSS-LOCAL-USER auth is not possible

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates