Bug 1378023

Summary: Exception acquiring ownership of X: TimeoutException (high load, invalidation cache and shared cache store)
Product: [JBoss] JBoss Enterprise Application Platform 6 Reporter: Michal Vinkler <mvinkler>
Component: ClusteringAssignee: Fedor Gavrilov <fgavrilo>
Status: CLOSED WONTFIX QA Contact: Michal Vinkler <mvinkler>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.4.8CC: fgavrilo, paul.ferraro
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-28 15:01:50 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Michal Vinkler 2016-09-21 10:49:11 UTC 
We can see "JBWEB000233: Exception sending request initialized lifecycle event to listener instance of class org.jboss.weld.servlet.WeldListener: java.lang.RuntimeException: JBAS018060: Exception acquiring ownership of EZtfWTXQ2-P92ukOc+3gxnfD" error message in the EAP server logs in our failover tests with invalidation cache and shared cache store.

Scenario description:
HTTP traffic accessing clustered web application that has replicated sessions (uses a mod_cluster load balancer). Delay between sending a new request after receiving a response is 2000 ms (for each client). Session size is 34 KB.
4-node EAP cluster + 4-node JDG cluster, one EAP node at time is shut down and after some time started again, while 6000 standalone clients keep calling the application.

Configuration:
 - 4-node EAP cluster with an invalidation cache + a shared cache store (remote JDG cluster)
 - 4-node JDG cluster with distributed cache
 - 4 nodes generating load (6000 clients in total)
 - cache mode: SYNC (for both invalidation and distributed caches, also "write-behind" element is set for "remote-store" element accordingly)

Links to configuration files:
EAP http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-stressfailover-remote-jdg-session-shutdown-invalidation-sync-4nodes-perf17/3/artifact/report/config/jboss-perf18/standalone-ha.xml
JDG http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-stressfailover-remote-jdg-session-shutdown-invalidation-sync-4nodes-perf17/3/artifact/report/config/jboss-perf22/clustered.xml

With no direct connection to shutdown of any node, perf20 started logging these exceptions and warning messages (total number of exceptions logged: 173):

JBossINF] [0m[31m06:38:06,477 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[default-host]] (ajp-perf20/10.16.90.58:8009-2586) JBWEB000233: Exception sending request initialized lifecycle event to listener instance of class org.jboss.weld.servlet.WeldListener: java.lang.RuntimeException: JBAS018060: Exception acquiring ownership of EZtfWTXQ2-P92ukOc+3gxnfD
[JBossINF] 	at org.jboss.as.web.session.ClusteredSession.access(ClusteredSession.java:494) [jboss-as-web-7.5.8.Final-redhat-2-bz-1370648.jar:7.5.8.Final-redhat-SNAPSHOT]
[JBossINF] 	at org.apache.catalina.connector.Request.doGetSession(Request.java:2638) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.connector.Request.getSession(Request.java:2382) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.connector.RequestFacade.getSession(RequestFacade.java:791) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.jboss.weld.context.beanstore.http.LazySessionBeanStore.getSession(LazySessionBeanStore.java:73) [weld-core-1.1.33.Final-redhat-1.jar:1.1.33.Final-redhat-1]
[JBossINF] 	at org.jboss.weld.context.beanstore.http.LazySessionBeanStore.<init>(LazySessionBeanStore.java:59) [weld-core-1.1.33.Final-redhat-1.jar:1.1.33.Final-redhat-1]
[JBossINF] 	at org.jboss.weld.context.http.HttpSessionContextImpl.associate(HttpSessionContextImpl.java:39) [weld-core-1.1.33.Final-redhat-1.jar:1.1.33.Final-redhat-1]
[JBossINF] 	at org.jboss.weld.context.http.HttpSessionContextImpl.associate(HttpSessionContextImpl.java:22) [weld-core-1.1.33.Final-redhat-1.jar:1.1.33.Final-redhat-1]
[JBossINF] 	at org.jboss.weld.servlet.WeldListener.requestInitialized(WeldListener.java:212) [weld-core-1.1.33.Final-redhat-1.jar:1.1.33.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:344) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:490) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:420) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:926) [jbossweb-7.5.16.Final-redhat-1.jar:7.5.16.Final-redhat-1]
[JBossINF] 	at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_91]
[JBossINF] Caused by: org.jboss.as.clustering.lock.TimeoutException: JBAS010213: Cannot acquire lock default-host/clusterbench-offload/EZtfWTXQ2-P92ukOc+3gxnfD from cluster
[JBossINF] 	at org.jboss.as.clustering.lock.SharedLocalYieldingClusterLockManager.throwTimeoutException(SharedLocalYieldingClusterLockManager.java:560)
[JBossINF] 	at org.jboss.as.clustering.lock.SharedLocalYieldingClusterLockManager.lock(SharedLocalYieldingClusterLockManager.java:478)
[JBossINF] 	at org.jboss.as.clustering.web.infinispan.DistributedCacheManager.acquireSessionOwnership(DistributedCacheManager.java:400)
[JBossINF] 	at org.jboss.as.web.session.ClusteredSession.acquireSessionOwnership(ClusteredSession.java:520) [jboss-as-web-7.5.8.Final-redhat-2-bz-1370648.jar:7.5.8.Final-redhat-SNAPSHOT]
[JBossINF] 	at org.jboss.as.web.session.ClusteredSession.access(ClusteredSession.java:492) [jboss-as-web-7.5.8.Final-redhat-2-bz-1370648.jar:7.5.8.Final-redhat-SNAPSHOT]
[JBossINF] 	... 16 more
[JBossINF] 
[JBossINF] [0m[33m06:38:06,538 WARN  [org.jboss.weld.Servlet] (ajp-perf20/10.16.90.58:8009-2586) WELD-000714 HttpContextLifecycle guard leak detected. The Servlet container is not fully compliant. The value was 1
[JBossINF] [0m[33m06:38:06,567 WARN  [org.jboss.weld.Context] (ajp-perf20/10.16.90.58:8009-2586) WELD-000223 Bean store leak was detected during org.jboss.weld.context.http.HttpRequestContextImpl association: org.apache.catalina.connector.RequestFacade@11a1ce19



Link to the server log:
http://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-stressfailover-remote-jdg-session-shutdown-invalidation-sync-4nodes-perf17/3/console-perf20/