You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@jackrabbit.apache.org by Ian Boston <ie...@tfd.co.uk> on 2010/10/18 21:38:30 UTC
relentless InvalidItemStateException
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)
Re: relentless InvalidItemStateException
Posted by Ian Boston <ie...@tfd.co.uk>.
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)
>>>
>>>
>>>
>>
>
Re: relentless InvalidItemStateException
Posted by Ian Boston <ie...@tfd.co.uk>.
Jukka,
Thanks, it was concurrent modification of the same Item ( I feel a bit stupid for not seeing it earlier).
When I say "removed synchronization" I didn't delete the synchronized wrappers, I ensured that the SystemSession was not shared between threads (by binding a SystemSession instance to each thread) an ensured that the EventListener.onEvent methods did not use a SystemSession, rather put a list of interesting events into a concurrent queue to be processed next time the owning thread does some work.
I had a look at applying JCR-2699 which looks like it will remove some of the lower level blocking but unfortunately the patches between 2.1.1 and HEAD are too great for us to use. We are 2 weeks past our release date. I think we will have to wait till 2.2 comes out for that.
Thanks
Ian
On 19 Oct 2010, at 10:17, Jukka Zitting wrote:
> Hi,
>
> On Tue, Oct 19, 2010 at 10:44 AM, Ian Boston <ie...@tfd.co.uk> wrote:
>> Any ideas ?
>
> We've typically seen such problems in cases where a client application
> has been using the same session from multiple concurrent threads,
> which is why we eventually decided to implement explicit
> synchronization of session access in JCR-890.
>
> I'm not sure if this is the cause of the problem also in your case,
> but it seems likely given your note about removed synchronization
> code. That code is there in Jackrabbit for a purpose and while such
> syncronizations can and should be removed (see for example the work on
> JCR-2699), doing so requires a pretty careful examination of potential
> unwanted side-effects. It would be great if you could file your
> changes as tightly scoped patches in Jira so we could better review
> them and perhaps point out potential problems.
>
> BR,
>
> Jukka Zitting
Re: relentless InvalidItemStateException
Posted by Jukka Zitting <ju...@gmail.com>.
Hi,
On Tue, Oct 19, 2010 at 10:44 AM, Ian Boston <ie...@tfd.co.uk> wrote:
> Any ideas ?
We've typically seen such problems in cases where a client application
has been using the same session from multiple concurrent threads,
which is why we eventually decided to implement explicit
synchronization of session access in JCR-890.
I'm not sure if this is the cause of the problem also in your case,
but it seems likely given your note about removed synchronization
code. That code is there in Jackrabbit for a purpose and while such
syncronizations can and should be removed (see for example the work on
JCR-2699), doing so requires a pretty careful examination of potential
unwanted side-effects. It would be great if you could file your
changes as tightly scoped patches in Jira so we could better review
them and perhaps point out potential problems.
BR,
Jukka Zitting
Re: relentless InvalidItemStateException
Posted by Ian Boston <ie...@tfd.co.uk>.
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)
>>
>>
>>
>
Re: relentless InvalidItemStateException
Posted by Ian Boston <ie...@tfd.co.uk>.
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)
>
>
>