jackrabbit-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ian Boston <...@tfd.co.uk>
Subject Re: relentless InvalidItemStateException
Date Tue, 19 Oct 2010 10:16:32 GMT
I have found the problem, 
Its normal for Jackrabbit.
The JMeter test was using a pattern for Groups of the form tester1234 which generates very
high contention on a single subfolder. /t/te/tes Its a well known issue that concurrent additions
of children to an Item in Jackrabbit cause InvalidItemStateExceptions. Unfortunately there
is no fix other than to avoid a 
content structure that results in high levels of concurrent modifications.

I should have spotted this ages ago, however since we were modifying lots of nodes the Exceptions
pointed to modifications at the root node which threw me off the sent.
Sorry for any alarm.
Ian

 
On 19 Oct 2010, at 09:44, Ian Boston wrote:

> Another one along the same lines.
> AFAICT, we add a node, it gets a UUID added but when it comes to saving the node the
child node has disappeared from the HierachyManager at line 291 (JR2.1.1) because the parent
NodeState didn't have the child node, that state being stored in a LinkedMap. Presumable because
it got removed. I will add some logging of Node IDs in ItemState to see if that happens.
> 
> This appears to be happening a lot concurrently under moderate load (12 concurrent request
threads in Jmeter). Works perfectly sequentially or under low load.
> 
> I should admit that we have removed quite a bit of blocking and synchronisation in the
code base surrounding Sessions in the AccessControlProviders blocking other sessions  and
restructured some of the Event Listeners to avoid sharing sessions between threads, but made
no changes below the Session level. All of this has made Jackrabbit non sequential on read,
but could be exposing bugs that anyone using the standard DefaultAccessManager just would
not see. Unfortunately, we have to be able to run the server non single threaded, so cant
live without those changes.
> 
> Any ideas ?
> 
> Thanks
> Ian
> 
> 
> 19.10.2010 09:18:58.531 *INFO* [127.0.0.1 [1287476338438] POST /system/userManager/group.create.json
HTTP/1.1] org.sakaiproject.nakamura.user.servlet.CreateSakaiGroupServlet Failed to create
group Unable to update item: node / javax.jcr.RepositoryException: Unable to update item:
node /
> 	at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:1156)
> 	at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:920)
> 	at org.apache.jackrabbit.core.security.user.UserManagerImpl.createGroup(UserManagerImpl.java:500)
> 	at org.apache.jackrabbit.core.security.user.UserManagerImpl.createGroup(UserManagerImpl.java:468)
> 	at org.sakaiproject.nakamura.user.servlet.CreateSakaiGroupServlet.handleOperation(CreateSakaiGroupServlet.java:292)
> 	at org.apache.sling.jackrabbit.usermanager.impl.post.AbstractAuthorizablePostServlet.doPost(AbstractAuthorizablePostServlet.java:127)
> 	at org.apache.sling.api.servlets.SlingAllMethodsServlet.mayService(SlingAllMethodsServlet.java:148)
> 	at org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:344)
> 	at org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:375)
> 	at org.apache.sling.engine.impl.request.RequestData.service(RequestData.java:523)
> 	at org.apache.sling.engine.impl.SlingMainServlet.processRequest(SlingMainServlet.java:427)
> 	at org.apache.sling.engine.impl.filter.RequestSlingFilterChain.render(RequestSlingFilterChain.java:48)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:64)
> 	at org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter.doFilter(RequestProgressTrackerLogFilter.java:59)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.batch.RequestEventsFilter.doFilter(RequestEventsFilter.java:96)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.files.pool.ContentPoolFilter.doFilter(ContentPoolFilter.java:77)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.privacy.RestPrivacyFilter.doFilter(RestPrivacyFilter.java:81)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.persistence.TransactionManagerFilter.doFilter(TransactionManagerFilter.java:95)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.cluster.ClusterTrackingFilter.doFilter(ClusterTrackingFilter.java:87)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.sakaiproject.nakamura.http.cache.CacheControlFilter.doFilter(CacheControlFilter.java:198)
> 	at org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:60)
> 	at org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:313)
> 	at org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:207)
> 	at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
> 	at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
> 	at org.ops4j.pax.web.service.internal.HttpServiceServletHandler.handle(HttpServiceServletHandler.java:64)
> 	at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
> 	at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
> 	at org.ops4j.pax.web.service.internal.HttpServiceContext.handle(HttpServiceContext.java:111)
> 	at org.ops4j.pax.web.service.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:64)
> 	at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
> 	at org.mortbay.jetty.Server.handle(Server.java:324)
> 	at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:535)
> 	at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:880)
> 	at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
> 	at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
> 	at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
> 	at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
> 	at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)
> Caused by: org.apache.jackrabbit.core.state.ItemStateException: Unable to resolve path
for item: 3e5d581b-986b-386d-a83e-83a0acee0674/{http://www.jcp.org/jcr/1.0}uuid
> 	at org.apache.jackrabbit.core.observation.EventStateCollection.getPath(EventStateCollection.java:683)
> 	at org.apache.jackrabbit.core.observation.EventStateCollection.createEventStates(EventStateCollection.java:435)
> 	at org.apache.jackrabbit.core.state.SharedItemStateManager$Update.begin(SharedItemStateManager.java:709)
> 	at org.apache.jackrabbit.core.state.SharedItemStateManager.beginUpdate(SharedItemStateManager.java:1455)
> 	at org.apache.jackrabbit.core.state.SharedItemStateManager.update(SharedItemStateManager.java:1485)
> 	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:328)
> 	at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:1150)
> 	... 44 more
> Caused by: javax.jcr.ItemNotFoundException: failed to build path of 3e5d581b-986b-386d-a83e-83a0acee0674:
b8984547-0d1f-42b3-bf9f-8684449f2fb3 has no child entry for 3e5d581b-986b-386d-a83e-83a0acee0674
> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.buildPath(HierarchyManagerImpl.java:291)
> 	at org.apache.jackrabbit.core.CachingHierarchyManager.buildPath(CachingHierarchyManager.java:198)
> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.buildPath(HierarchyManagerImpl.java:280)
> 	at org.apache.jackrabbit.core.CachingHierarchyManager.buildPath(CachingHierarchyManager.java:198)
> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.getPath(HierarchyManagerImpl.java:395)
> 	at org.apache.jackrabbit.core.CachingHierarchyManager.getPath(CachingHierarchyManager.java:232)
> 	at org.apache.jackrabbit.core.observation.EventStateCollection.getPath(EventStateCollection.java:678)
> 	... 53 more
> 
> 
> On 18 Oct 2010, at 22:06, Ian Boston wrote:
> 
>> I also get things like this:
>> 
>> 1-ad9e-4574-8f6c-9545a7e3ba5b: b65ef847-0127-4a3b-9260-86012124616a has no child
entry for a99b9f31-ad9e-4574-8f6c-9545a7e3ba5b javax.jcr.ItemNotFoundException: failed to
build path of a99b9f31-ad9e-4574-8f6c-9545a7e3ba5b: b65ef847-0127-4a3b-9260-86012124616a has
no child entry for a99b9f31-ad9e-4574-8f6c-9545a7e3ba5b
>> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.buildPath(HierarchyManagerImpl.java:291)
>> 	at org.apache.jackrabbit.core.CachingHierarchyManager.buildPath(CachingHierarchyManager.java:198)
>> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.buildPath(HierarchyManagerImpl.java:280)
>> 	at org.apache.jackrabbit.core.CachingHierarchyManager.buildPath(CachingHierarchyManager.java:198)
>> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.buildPath(HierarchyManagerImpl.java:280)
>> 	at org.apache.jackrabbit.core.CachingHierarchyManager.buildPath(CachingHierarchyManager.java:198)
>> 	at org.apache.jackrabbit.core.HierarchyManagerImpl.getPath(HierarchyManagerImpl.java:395)
>> 	at org.apache.jackrabbit.core.CachingHierarchyManager.getPath(CachingHierarchyManager.java:232)
>> 	at org.apache.jackrabbit.core.lock.LockManagerImpl.getPath(LockManagerImpl.java:856)
>> 	at org.apache.jackrabbit.core.lock.LockManagerImpl.checkLock(LockManagerImpl.java:702)
>> 	at org.apache.jackrabbit.core.lock.XALockManager.checkLock(XALockManager.java:174)
>> 	at org.apache.jackrabbit.core.ItemValidator.checkLock(ItemValidator.java:392)
>> 	at org.apache.jackrabbit.core.ItemValidator.checkCondition(ItemValidator.java:315)
>> 	at org.apache.jackrabbit.core.ItemValidator.checkModify(ItemValidator.java:277)
>> 	at org.apache.jackrabbit.core.NodeImpl.checkSetProperty(NodeImpl.java:1207)
>> 	at org.apache.jackrabbit.core.NodeImpl.setProperty(NodeImpl.java:2341)
>> 	at org.apache.jackrabbit.core.NodeImpl.setProperty(NodeImpl.java:1596)
>> 	at org.apache.jackrabbit.core.NodeImpl.setProperty(NodeImpl.java:2216)
>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.updateProfileProperties(PersonalAuthorizablePostProcessor.java:219)
>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.createHomeFolder(PersonalAuthorizablePostProcessor.java:287)
>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.process(PersonalAuthorizablePostProcessor.java:156)
>> 
>> 
>> On 18 Oct 2010, at 20:38, Ian Boston wrote:
>> 
>>> Hi,
>>> I am having persistent/relentless problems with InvalidItemStateExceptions of
the form  below. In this http request there are multiple save operations, and when there are,
under load (12 concurrent threads) I get random InvalidItemStateExceptions.
>>> 
>>> They can take 1000s of requests to happen or they can take just a few. Each request
has a unique path so I am reasonably certain no 2 requests are modifying the same node. If
I remove some of the save() operation, then the occurrence drops leading me to think that
there is a problem with doing a sequence of session.save operations.
>>> 
>>> I am also reasonably certain that there are no Observation managers making changes
in other threads, or SystemSessions making modifications in access control providers and the
like. The test is being run against a single node, no cluster, ClusterNode or Journal that
could be modifying.
>>> 
>>> Even Stranger is sometimes it reports InvalidItemState on the root node /, but
that might have been before I eliminated all Workspace.copy() operations.
>>> 
>>> any ideas, I am a bit stuck on this "bug" having been at it for 3 days.
>>> 
>>> Ian
>>> 
>>> 18.10.2010 20:29:05.814 *ERROR* [127.0.0.1 [1287430145192] POST /system/userManager/group.create.json
HTTP/1.1] org.sakaiproject.nakamura.personal.ProfileImporter Unable to import content for
profile node node /_group/t/te/tes/test/teste/tester4_gr1_14_4/public/authprofile javax.jcr.InvalidItemStateException:
Item cannot be saved because it has been modified externally: node /
>>> 	at org.apache.jackrabbit.core.ItemImpl.getTransientStates(ItemImpl.java:249)
>>> 	at org.apache.jackrabbit.core.ItemImpl.save(ItemImpl.java:981)
>>> 	at org.apache.jackrabbit.core.SessionImpl.save(SessionImpl.java:920)
>>> 	at org.apache.sling.jcr.contentloader.internal.DefaultContentImporter.importContent(DefaultContentImporter.java:112)
>>> 	at org.sakaiproject.nakamura.personal.ProfileImporter.importFromJsonString(ProfileImporter.java:102)
>>> 	at org.sakaiproject.nakamura.personal.ProfileImporter.importFromParameters(ProfileImporter.java:90)
>>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.updateProfileProperties(PersonalAuthorizablePostProcessor.java:191)
>>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.createHomeFolder(PersonalAuthorizablePostProcessor.java:287)
>>> 	at org.sakaiproject.nakamura.personal.PersonalAuthorizablePostProcessor.process(PersonalAuthorizablePostProcessor.java:156)
>>> 	at org.sakaiproject.nakamura.user.AuthorizablePostProcessServiceImpl.process(AuthorizablePostProcessServiceImpl.java:132)
>>> 	at org.sakaiproject.nakamura.user.AuthorizablePostProcessServiceImpl.process(AuthorizablePostProcessServiceImpl.java:167)
>>> 
>>> 
>>> 
>> 
> 


Mime
View raw message