Bug 1330867

Summary: org.apache.jackrabbit.core.state.StaleItemStateException for inbox in BRMS 5 cluster
Product: [JBoss] JBoss Enterprise BRMS Platform 5 Reporter: Toshiya Kobayashi <tkobayas>
Component: BRM (Guvnor)Assignee: manstis
Status: NEW --- QA Contact: Jiri Locker <jlocker>
Severity: high Docs Contact:
Priority: unspecified    
Version: BRMS 5.3.1CC: mweiler
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
repository.xml
none
guvnor-rest-concurrent-add.zip
none
ConcurrentUpdateTest none

Description Toshiya Kobayashi 2016-04-27 07:47:10 UTC
Description of problem:

org.apache.jackrabbit.core.state.StaleItemStateException for inbox in BRMS 5 cluster

In BRMS 5 cluster (jackrabbit cluster is configured), you will get 2 kinds of org.apache.jackrabbit.core.state.StaleItemStateException for inbox when you add assets concurrently.


1. StaleItemStateException for user's inbox 'recentEdited' property
=====
016-04-27 15:30:14,436 ERROR [org.drools.repository.UserInfo] (http-127.0.0.1-8080-6) Unable to save
javax.jcr.InvalidItemStateException: Unable to update a stale item: item.save()
        at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:262)
        at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
        at org.apache.jackrabbit.core.ItemImpl.perform(ItemImpl.java:91)
        at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:329)
        at org.drools.repository.UserInfo.save(UserInfo.java:197)
        at org.drools.guvnor.server.repository.UserInbox.save(UserInbox.java:190)
        at org.drools.guvnor.server.repository.UserInbox.recordUserEditEvent(UserInbox.java:185)
        at org.drools.guvnor.server.repository.RepositoryStartupService$1.afterCheckin(RepositoryStartupService.java:110)
        at org.drools.repository.events.StorageEventManager.doCheckinEvents(StorageEventManager.java:96)
        at org.drools.repository.VersionableItem.checkin(VersionableItem.java:588)
        at org.drools.guvnor.server.jaxrs.PackageResource.updateAssetFromAtom(PackageResource.java:713)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:173)
        at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:89)
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:165)
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:92)
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:58)
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:94)
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:263)
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121)
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:207)
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:209)
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:152)
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:114)
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:185)
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:125)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:640)
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:164)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.jboss.seam.web.ContextFilter$1.process(ContextFilter.java:42)
        at org.jboss.seam.servlet.ContextualHttpServletRequest.run(ContextualHttpServletRequest.java:65)
        at org.jboss.seam.web.ContextFilter.doFilter(ContextFilter.java:37)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:96)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:235)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
        at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:183)
        at org.jboss.web.tomcat.service.session.ClusteredSessionValve.handleRequest(ClusteredSessionValve.java:135)
        at org.jboss.web.tomcat.service.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:94)
        at org.jboss.web.tomcat.service.session.LockingValve.invoke(LockingValve.java:62)
        at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:95)
        at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.process(SecurityContextEstablishmentValve.java:126)
        at org.jboss.web.tomcat.security.SecurityContextEstablishmentValve.invoke(SecurityContextEstablishmentValve.java:70)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.jboss.web.tomcat.service.jca.CachedConnectionValve.invoke(CachedConnectionValve.java:158)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
        at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.internalProcess(ActiveRequestResponseCacheValve.java:74)
        at org.jboss.web.tomcat.service.request.ActiveRequestResponseCacheValve.invoke(ActiveRequestResponseCacheValve.java:47)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:330)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:829)
        at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:599)
        at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:451)
        at java.lang.Thread.run(Thread.java:662)
Caused by: org.apache.jackrabbit.core.state.StaleItemStateException: df2e7746-f7c1-4d67-9f83-b51ec93a18b4/{}recentEdited has been modified externally
        at org.apache.jackrabbit.core.state.SharedItemStateManager$Update.begin(SharedItemStateManager.java:663)
        at org.apache.jackrabbit.core.state.SharedItemStateManager.beginUpdate(SharedItemStateManager.java:1458)
        at org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:1488)
        at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:351)
        at org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:354)
        at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:326)
        at org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:289)
        at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:258)
        ... 60 more
====

2. StaleItemStateException for mailman's inbox 'incoming' property

====
2016-04-27 15:39:26,779 ERROR [org.drools.repository.RulesRepository] (pool-17-thread-1) Caught Exception
javax.jcr.InvalidItemStateException: Unable to update a stale item: item.save()
        at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:262)
        at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
        at org.apache.jackrabbit.core.ItemImpl.perform(ItemImpl.java:91)
        at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:329)
        at org.apache.jackrabbit.core.session.SessionSaveOperation.perform(SessionSaveOperation.java:42)
        at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
        at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:355)
        at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:758)
        at org.drools.repository.RulesRepository.save(RulesRepository.java:1408)
        at org.drools.guvnor.server.repository.MailboxService.processOutgoing(MailboxService.java:115)
        at org.drools.guvnor.server.repository.MailboxService$3.run(MailboxService.java:142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
        at java.lang.Thread.run(Thread.java:662)
Caused by: org.apache.jackrabbit.core.state.StaleItemStateException: 33a8fa57-d50d-4f71-bce1-d84007f26da1/{}incoming has been modified externally
        at org.apache.jackrabbit.core.state.SharedItemStateManager$Update.begin(SharedItemStateManager.java:663)
        at org.apache.jackrabbit.core.state.SharedItemStateManager.beginUpdate(SharedItemStateManager.java:1458)
        at org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:1488)
        at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:351)
        at org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:354)
        at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:326)
        at org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:289)
        at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:258)
        ... 13 more
====

Especially in the latter case, once you hit the issue, the Exception will keep occurring even with a non-concurrent access.


Version-Release number of selected component (if applicable):

Reproduced with
- BRMS 5.3.1.GA (on EAP 5)
- BRMS 5.3.1 roll-up #5 (on EAP 6)

How reproducible:

Easy to reproduce with concurrent updates.

Steps to Reproduce:
1. Set up BRMS 5.3.1 cluster (attached repository.xml for MySQL FYI)
2. Start the cluster
3. Run the reproducer (download and unzip guvnor-rest-concurrent-add.zip)
$ mvn clean test

Actual results:

Throws StaleItemStateException in server side as above.

Expected results:

No Exception.

Comment 1 Toshiya Kobayashi 2016-04-27 07:49:06 UTC
Created attachment 1151245 [details]
repository.xml

Comment 2 Toshiya Kobayashi 2016-04-27 07:52:18 UTC
Created attachment 1151246 [details]
guvnor-rest-concurrent-add.zip

Comment 3 Toshiya Kobayashi 2016-04-28 09:50:56 UTC
The 1st case "StaleItemStateException for user's inbox 'recentEdited' property" can be avoided by using different users.

Comment 4 Martin Weiler 2016-04-28 12:32:18 UTC
Toshiya found a third issue that results in a race condition:

3. StaleItemStateException for "package's binaryUpToDate"

====
18:14:25,424 ERROR [STDERR] org.drools.repository.RulesRepositoryException: Unable to checkin.
18:14:25,424 ERROR [STDERR] 	at org.drools.repository.VersionableItem.checkin(VersionableItem.java:591)
18:14:25,424 ERROR [STDERR] 	at org.drools.guvnor.server.jaxrs.PackageResource.updateAssetBinary(PackageResource.java:773)
...
18:14:25,427 ERROR [STDERR] Caused by: javax.jcr.InvalidItemStateException: Unable to update a stale item: item.save()
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:262)
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.ItemImpl.perform(ItemImpl.java:91)
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:329)
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.session.SessionSaveOperation.perform(SessionSaveOperation.java:42)
18:14:25,427 ERROR [STDERR] 	at org.apache.jackrabbit.core.session.SessionState.perform(SessionState.java:200)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.SessionImpl.perform(SessionImpl.java:355)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:758)
18:14:25,428 ERROR [STDERR] 	at org.drools.repository.VersionableItem.checkin(VersionableItem.java:579)
18:14:25,428 ERROR [STDERR] 	... 51 more
18:14:25,428 ERROR [STDERR] Caused by: org.apache.jackrabbit.core.state.StaleItemStateException: 1547b59e-cc22-4fb5-ae0e-8ce1c15e8299/{http://www.jboss.org/drools-repository/1.0}binaryUpToDate has been modified externally
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.SharedItemStateManager$Update.begin(SharedItemStateManager.java:663)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.SharedItemStateManager.beginUpdate(SharedItemStateManager.java:1458)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:1488)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:351)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.XAItemStateManager.update(XAItemStateManager.java:354)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.LocalItemStateManager.update(LocalItemStateManager.java:326)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.state.SessionItemStateManager.update(SessionItemStateManager.java:289)
18:14:25,428 ERROR [STDERR] 	at org.apache.jackrabbit.core.ItemSaveOperation.perform(ItemSaveOperation.java:258)
18:14:25,428 ERROR [STDERR] 	... 59 more
====

This is caused by concurrent updates for assets in the same package. No matter if the same user or different users. It happens even in one node.

The bad part is that we cannot see the Exception if we don't recompile PackageResource with "e.printStackTrace()". REST Client just gets 500.

Comment 5 Martin Weiler 2016-04-28 12:35:26 UTC
Created attachment 1151847 [details]
ConcurrentUpdateTest

Attaching BRMS531Ex77_rest_concurrentUpdate.zip from Toshiya which helps to test on your side. See README.txt inside.