Unexpected concurrency warning

[federicos727792]

Hi,

I've created a java class that runs a content restructuring process when invoked. It makes use of a JCR session obtained through the request on a sling servlet. The process does various things: deletes nodes with subtrees, copies nodes, creates properties, tweaks LiveSync mixins, etc.  The process is single threaded, however I see msgs like this in the log:

11.10.2016 16:49:26.203 *WARN* [Thread-79] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getItemOrNull while thread Thread-74 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 11.10.2016 16:49:26.553 *WARN* [Thread-74] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-79 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

Can anyone explain this? Even if it is a performance warning, I don't understand why there're multiple threads. The mentioned methods also match the ones I'm invoking. I find hard to believe that an invocation to the JCR will use a different thread and then hand over the result to my thread.

It has been mentioned to me that some observers might be triggered and those might run on a different thread. This would match the fact that my process finishes without problems, but some of this messages in the log appear after that.

In fact I also get some errors:

11.10.2016 16:49:32.607 *ERROR* [Thread-79] com.day.cq.wcm.msm.impl.RolloutManagerImpl Failed to save changes {}, revert javax.jcr.InvalidItemStateException: OakState0001: Unresolved conflicts in /content/xxx/xx/xxx/destinations/australia/jcr:content at org.apache.jackrabbit.oak.api.CommitFailedException.asRepositoryException(CommitFailedException.java:237) at org.apache.jackrabbit.oak.api.CommitFailedException.asRepositoryException(CommitFailedException.java:212) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.newRepositoryException(SessionDelegate.java:594) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.save(SessionDelegate.java:461) at org.apache.jackrabbit.oak.jcr.session.SessionImpl$8.perform(SessionImpl.java:435) at org.apache.jackrabbit.oak.jcr.session.SessionImpl$8.perform(SessionImpl.java:432) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.perform(SessionDelegate.java:216) at org.apache.jackrabbit.oak.jcr.session.SessionImpl.perform(SessionImpl.java:140) at org.apache.jackrabbit.oak.jcr.session.SessionImpl.save(SessionImpl.java:432) at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:497) at org.apache.sling.jcr.base.SessionProxyHandler$SessionProxyInvocationHandler.invoke(SessionProxyHandler.java:113) at com.sun.proxy.$Proxy8.save(Unknown Source) at com.day.cq.wcm.msm.impl.RolloutManagerImpl.save(RolloutManagerImpl.java:1053) at com.day.cq.wcm.msm.impl.RolloutManagerImpl.access$1200(RolloutManagerImpl.java:106) at com.day.cq.wcm.msm.impl.RolloutManagerImpl$PageEventProcessor.call(RolloutManagerImpl.java:1198) at com.day.cq.wcm.msm.impl.RolloutManagerImpl$PageEventProcessor.call(RolloutManagerImpl.java:1152) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) Caused by: org.apache.jackrabbit.oak.api.CommitFailedException: OakState0001: Unresolved conflicts in /content/xxx/xx/xx/destinations/australia/jcr:content at org.apache.jackrabbit.oak.plugins.commit.ConflictValidator.failOnMergeConflict(ConflictValidator.java:84) at org.apache.jackrabbit.oak.plugins.commit.ConflictValidator.propertyChanged(ConflictValidator.java:60) at org.apache.jackrabbit.oak.spi.commit.CompositeEditor.propertyChanged(CompositeEditor.java:91) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.propertyChanged(EditorDiff.java:93) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareProperties(SegmentNodeState.java:596) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:456) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.childNodeChanged(EditorDiff.java:148) at org.apache.jackrabbit.oak.plugins.segment.MapRecord.compare(MapRecord.java:418) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareAgainstBaseState(SegmentNodeState.java:583) at org.apache.jackrabbit.oak.spi.commit.EditorDiff.process(EditorDiff.java:52) at org.apache.jackrabbit.oak.spi.commit.EditorHook.processCommit(EditorHook.java:54) at org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:61) at org.apache.jackrabbit.oak.spi.commit.CompositeHook.processCommit(CompositeHook.java:61) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStore$Commit.prepare(SegmentNodeStore.java:405) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStore$Commit.optimisticMerge(SegmentNodeStore.java:428) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStore$Commit.execute(SegmentNodeStore.java:484) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeStore.merge(SegmentNodeStore.java:162) at org.apache.jackrabbit.oak.spi.state.ProxyNodeStore.merge(ProxyNodeStore.java:43) at org.apache.jackrabbit.oak.core.MutableRoot.commit(MutableRoot.java:247) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.commit(SessionDelegate.java:313) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.save(SessionDelegate.java:459) ... 18 common frames omitted

Any suggestions?

Thx.

[Feike_Visser1]

Any code you can share, make sure you don't use class variables to hold JCR-sessions / ResourceResolver.

[federicos727792]

> Any code you can share, make sure you don't use class variables to hold JCR-sessions / ResourceResolver.

I'll try to share some relevant pieces. Definitely not storing any sessions at the class level. Logging shows that always the same session is used (when looking at the audit log using debug level), but different threads as shown above.

In the save vein as above I just got this error:

14.10.2016 11:20:33.469 *WARN* [Thread-72] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-74 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:34.873 *WARN* [Thread-72] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getProperties while thread Thread-74 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:35.155 *WARN* [Thread-72] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-74 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:37.619 *ERROR* [Thread-74] com.day.cq.wcm.msm.impl.RolloutManagerImpl Failed to save changes {}, revert javax.jcr.InvalidItemStateException: OakState0001: Unresolved conflicts in /content/xxx/cn/zh_CN/destinations/australia/jcr:content at org.apache.jackrabbit.oak.api.CommitFailedException.asRepositoryException(CommitFailedException.java:237) at org.apache.jackrabbit.oak.api.CommitFailedException.asRepositoryException(CommitFailedException.java:212) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.newRepositoryException(SessionDelegate.java:594)         ... at org.apache.sling.jcr.base.SessionProxyHandler$SessionProxyInvocationHandler.invoke(SessionProxyHandler.java:113) at com.sun.proxy.$Proxy8.save(Unknown Source) at com.day.cq.wcm.msm.impl.RolloutManagerImpl.save(RolloutManagerImpl.java:1053) at com.day.cq.wcm.msm.impl.RolloutManagerImpl.access$1200(RolloutManagerImpl.java:106) at com.day.cq.wcm.msm.impl.RolloutManagerImpl$PageEventProcessor.call(RolloutManagerImpl.java:1198) at com.day.cq.wcm.msm.impl.RolloutManagerImpl$PageEventProcessor.call(RolloutManagerImpl.java:1152) at java.util.concurrent.FutureTask.run(FutureTask.java:266)         ... at org.apache.jackrabbit.oak.spi.commit.EditorDiff.propertyChanged(EditorDiff.java:93) at org.apache.jackrabbit.oak.plugins.segment.SegmentNodeState.compareProperties(SegmentNodeState.java:596)         ... at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.save(SessionDelegate.java:459) ... 18 common frames omitted 14.10.2016 11:20:37.620 *ERROR* [Thread-74] com.day.cq.wcm.msm.impl.RolloutManagerImpl Exception during process of event {} com.day.cq.wcm.api.WCMException: javax.jcr.InvalidItemStateException: OakState0001: Unresolved conflicts in /content/xxx/cn/zh_CN/destinations/australia/jcr:content at com.day.cq.wcm.msm.impl.RolloutManagerImpl.save(RolloutManagerImpl.java:1059)         ... at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.commit(SessionDelegate.java:313) at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.save(SessionDelegate.java:459) ... 18 common frames omitted 14.10.2016 11:20:37.770 *WARN* [Thread-75] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getItemOrNull while thread Thread-73 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:37.785 *WARN* [Thread-73] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-75 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:38.188 *WARN* [Thread-73] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getItemOrNull while thread Thread-75 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:38.305 *WARN* [Thread-73] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-75 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session. 14.10.2016 11:20:38.351 *WARN* [Thread-73] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform hasProperty while thread Thread-75 was concurrently writing to this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

To me the interesting part is the RolloutManagerImpl which is not triggered by me. So it seems that it is indeed observing the repository and changing things concurrently while my process is still running. Is there a way to disable it and activate when the process is done?

[Jörg_Hoh · Accepted solution]

Hi,

I guess that you run into some issues at the MSM level, there might be a shared session in some MSM-related services. The exception is something you should care about, there seems to be a conflict when writing to the content and the subsequent save.

I would report this to Daycare support and ask for the latest hotfix for MSM for the AEM version you are using.

Jörg

[federicos727792]

Thx for the suggestion Joerg.

The good thing is that I've updated my development environment with the latest 6.1 SP2 and haven't seen the problem since then. I'll report back if I do see it again.

Cheers,

Federico

[_SumitSinghal]

Hi,

Could you please share some information whether the commit conflict issue in MSM has been fixed on AEM6.2. As I am still facing this issue .

Thanks in advance