Random "the session has been closed" errors from AEM

[Balaram_Rudra]

Hello Experts,

I appreciate any insights into what could be causing the below errror:

Caused by: javax.jcr.RepositoryException: This session has been closed.
at org.apache.jackrabbit.oak.jcr.session.SessionImpl.checkAlive(SessionImpl.java:141)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl.getNodeById(SessionImpl.java:317)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl.getNodeByIdentifier(SessionImpl.java:340)
at com.adobe.granite.repository.impl.CRX3SessionImpl.getNodeByIdentifier(CRX3SessionImpl.java:163)

Some context into what we are doing, We receive a JSON file from a third party client on the AEM via a servlet. At times the file could be huge, so we run the file processing in a background thread and give  a asynchronous response to the client about the file reception.
As part of the file processing, we read and update data on JCR. To do this we create a service resourceResolver using a service user and then adapt it to a session. The problem is with this session being closed randomly in the processing of the file. Nothing explains the randomness of the issue.

[milind_bachani]

Hi @Balaram_Rudra ,

Are you explicitly closing the session using session.close() or session.logout()?
If yes, please move the session closing statement in finally block. The session needs to kept open till you are accessing the nodes.

Thanks.

[Balaram_Rudra]

Hi @milind_bachani ,
The session or the resourceResolver is not being closed explicitly as it is now. 

[milind_bachani]

@Balaram_Rudra In that case can you please close the same explicitly inside a finally block. And then try executing the code once. Thanks.

[Balaram_Rudra]

Noted @milind_bachani, that is on my bucket list to be addressed. But with regards to the session closure, there is no indication on the logs or jmx console that points to the session leakage that is causing it. So I still looking for the potential cause for the random closure of sessions

[Jörg_Hoh]

Hi,

I think this randomness is caused by the fact, that you are somehow passing a session/ResourceResolver from a the request into the background job/thread. And depending which one finishes first you might see the exception.

To see if that's really the case, turn on the DEBUG logging for the class "org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate".

It will log read access when more than 1 session performs reads on the same session. 

[Balaram_Rudra]

Hi @Jörg_Hoh 

We are creating a new resource resolved in the background thread using a service user. However, from the below error traces I could see that [Apache Sling Resource Resolver Finalizer Thread] is trying to close the session that is being used by the background thread.

Please look at the below error logs:

09.02.2022 18:54:02.294 *DEBUG* [Apache Sling Resource Resolver Finalizer Thread] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform logout while thread ForkJoinPool-9-worker-157 was concurrently reading from this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.

java.lang.Exception: Stack trace of concurrent access to session

at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:759)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$SynchronizedIterator.hasNext(SessionDelegate.java:691)
at org.apache.jackrabbit.oak.jcr.query.PrefetchIterator.size(PrefetchIterator.java:122)
at org.apache.jackrabbit.oak.jcr.query.QueryResultImpl$6.getSize(QueryResultImpl.java:228)
at ....stack from custom AEM project code
at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1386)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175) 

Also, the below error log:

09.02.2022 18:54:02.295 *DEBUG* [ForkJoinPool-9-worker-157] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getProperty while thread Apache Sling Resource Resolver Finalizer Thread was concurrently reading from this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.
java.lang.Exception: Stack trace of concurrent access to session

at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:759)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:773)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.performVoid(SessionDelegate.java:269)
at org.apache.jackrabbit.oak.jcr.session.SessionContext.unlockAllSessionScopedLocks(SessionContext.java:423)
at org.apache.jackrabbit.oak.jcr.session.SessionContext.dispose(SessionContext.java:405)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl$10.performVoid(SessionImpl.java:464)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.performVoid(SessionDelegate.java:274)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl.logout(SessionImpl.java:461)
at com.adobe.granite.repository.impl.CRX3SessionImpl.logout(CRX3SessionImpl.java:293)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrProviderState.logout(JcrProviderState.java:81)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrResourceProvider.logout(JcrResourceProvider.java:289)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrResourceProvider.logout(JcrResourceProvider.java:75)
at org.apache.sling.resourceresolver.impl.helper.ResourceResolverControl.logout(ResourceResolverControl.java:139)
at org.apache.sling.resourceresolver.impl.helper.ResourceResolverControl.close(ResourceResolverControl.java:677)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl.unregisterControl(CommonResourceResolverFactoryImpl.java:281)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl.access$300(CommonResourceResolverFactoryImpl.java:61)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl$ResolverReference.close(CommonResourceResolverFactoryImpl.java:5264595554 )
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl$1.run(CommonResourceResolverFactoryImpl.java:109)

It looks like the resouceResolverFactory is trying to close the resourceResolver from which the session is being adapted from, not sure why this is happening. We are also not able to replicate this issue in dev environment for us to debug or test any fixes. 

[Balaram_Rudra]

Hi Jorg,

We are creating a new resource resolved in the background thread using a service user. However, from the below error traces I could see that [Apache Sling Resource Resolver Finalizer Thread] is trying to close the session that is being used by the background thread.

Please look at the below error logs:
09.02.2022 18:54:02.294 *DEBUG* [Apache Sling Resource Resolver Finalizer Thread] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to
perform logout while thread ForkJoinPool-9-worker-157 was concurrently reading from this session. Blocked until the other thread finished using this s
ession. Please review your code to avoid concurrent use of a session.
java.lang.Exception: Stack trace of concurrent access to session
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:759)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$SynchronizedIterator.hasNext(SessionDelegate.java:691)
at org.apache.jackrabbit.oak.jcr.query.PrefetchIterator.size(PrefetchIterator.java:122)
at org.apache.jackrabbit.oak.jcr.query.QueryResultImpl$6.getSize(QueryResultImpl.java:228)
at ....stack from custom AEM project code
at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1386)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175) 
Also, the below error log:

09.02.2022 18:54:02.295 *DEBUG* [ForkJoinPool-9-worker-157] org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate Attempted to perform getProperty while thread Apache Sling Resource Resolver Finalizer Thread was concurrently reading from this session. Blocked until the other thread finished using this session. Please review your code to avoid concurrent use of a session.
java.lang.Exception: Stack trace of concurrent access to session
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:759)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:773)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.performVoid(SessionDelegate.java:269)
at org.apache.jackrabbit.oak.jcr.session.SessionContext.unlockAllSessionScopedLocks(SessionContext.java:423)
at org.apache.jackrabbit.oak.jcr.session.SessionContext.dispose(SessionContext.java:405)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl$10.performVoid(SessionImpl.java:464)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate.performVoid(SessionDelegate.java:274)
at org.apache.jackrabbit.oak.jcr.session.SessionImpl.logout(SessionImpl.java:461)
at com.adobe.granite.repository.impl.CRX3SessionImpl.logout(CRX3SessionImpl.java:293)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrProviderState.logout(JcrProviderState.java:81)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrResourceProvider.logout(JcrResourceProvider.java:289)
at org.apache.sling.jcr.resource.internal.helper.jcr.JcrResourceProvider.logout(JcrResourceProvider.java:75)
at org.apache.sling.resourceresolver.impl.helper.ResourceResolverControl.logout(ResourceResolverControl.java:139)
at org.apache.sling.resourceresolver.impl.helper.ResourceResolverControl.close(ResourceResolverControl.java:677)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl.unregisterControl(CommonResourceResolverFactoryImpl.java:281)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl.access$300(CommonResourceResolverFactoryImpl.java:61)
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl$ResolverReference.close(CommonResourceResolverFactoryImpl.java:5264595554 )
at org.apache.sling.resourceresolver.impl.CommonResourceResolverFactoryImpl$1.run(CommonResourceResolverFactoryImpl.java:109)

It looks like the resouceResolverFactory is trying to close the resourceResolver from which the session is being adapted from, not sure why this is happening. We are also not able to replicate this issue in dev environment for us to debug or test any fixes. 

[Jörg_Hoh]

Hi

java.lang.Exception: Stack trace of concurrent access to session
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$WarningLock.lock(SessionDelegate.java:759)
at org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate$SynchronizedIterator.hasNext(SessionDelegate.java:691)
at org.apache.jackrabbit.oak.jcr.query.PrefetchIterator.size(PrefetchIterator.java:122)
at org.apache.jackrabbit.oak.jcr.query.QueryResultImpl$6.getSize(QueryResultImpl.java:228)
at ....stack from custom AEM project code
at java.util.concurrent.ForkJoinTask$AdaptedRunnableAction.exec(ForkJoinTask.java:1386)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1056)
at java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1692)
at java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175) 

This log messages appears because multiple threads (of the fork-join pool) are reading from the same session. This is discouraged, every thread should have its own ResourceResolver. That would probably require you to rewrite the code and not to use a fork-join pool.

What is the behavior of the code which is executed in this fork-join pool? Is it closing the ResourceResolver? In this case you have multiple threads operating on the RR and one is closing the RR although the other threads have not yet completed their work.

Regarding the FinalizerThread: That's just a "final measure" to cleanup. You shouldn't worry about this one, although I wonder why it is reported as concurrent access.

[Balaram_Rudra]

Hi @Jörg_Hoh ,

The ResourceResolver is not being shared between the threads in the pool, each thread[in the work stealing threads] initiates its one ResourceResolver. The code in the thread is not closing the RR explicitly.
My observation is that the FinalizerThread is the only other thread that is trying to access[trying to close the RR while it is being used] the ResouceResolver besides the thread that created it.

[Jörg_Hoh]

Well, in that case the warning is correct (as the finalizers are running in a dedicated thread). But when the finalizer is taking care of closing the sessions, you forgot to close them

[Balaram_Rudra]

Thank you @Jörg_Hoh, But why should the finalizer close the resourceResolver that is created in the last second and is still busy actively reading/writing to the repo. Causing the code to break with error "The session has been closed".
What is the criteria for the finalizer to determine a resourceResolver as an unused one before trying to force closing it.

We also didn't find any evidence on the OSGI jmx console indicating any session leakages.

[kautuk_sahni]

@Anish-Sinha @lukasz-m @Asutosh_Jena_ @Vijayalakshmi_S Requet your help to this thread.

[milind_bachani]

@Balaram_Rudra hi,

Are you still facing the issue ? If yes, can you please share the pseudo code or code itself(if possible) to investigate further ?

Also, if the issue is fixed - can you post the solution applied by you so that the thread can be moved to the correct status, many thanks.

As per my understanding you should explicitly command over the sessions start and closure which can avoid such randomness, however happy to help if you can help with the code snippet causing the issue.

[Balaram_Rudra]

Hi @milind_bachani 
Yes, we are still facing the issue. I hope the below pseudo code helps. let me know if something is not clear.

BackgroundExecutor(OSGI Component) {
@Reference

ResourceResolverFactory resourceResolverFactory;

Activate() -> creates an executor service with work Stealing thread pool

Deactivate() -> executor shutdown

execute(executable) -> Submits a new task to the executor service, 

task() -> Creates a new service resource resolver from the ResourceResolverFactory and obtains a session from the RR and runs the executable using executable.run(session)

}

TestServlet{
@Reference

BackgroundExecutor bgExecutor;

doPost() -> bgExecutor.execute((session)=> processJSON(session, json)) 

processJSON(session, json) -> process the json using the session 
}