[MAGNOLIA-6729] Stale session on accessing JCR resources Created: 22/Jul/16  Updated: 03/Apr/17  Resolved: 27/Mar/17

Status: Closed
Project: Magnolia
Component/s: resource-loader
Affects Version/s: 5.4.7
Fix Version/s: 5.4.12, 5.5.3

Type: Bug Priority: Critical
Reporter: Richard Unger Assignee: Jaroslav Simak
Resolution: Fixed Votes: 2
Labels: support
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

LFRZ


Issue Links:
Relates
relates to MAGNOLIA-6664 Inheritance of registry definitions f... Closed
causality
Template:
Patch included:
Yes
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Bug DoR:
[ ]* Steps to reproduce, expected, and actual results filled
[ ]* Affected version filled
Date of First Response:
Sprint: Kromeriz 89
Story Points: 2

 Description   

Originally reported as SUPPORT-6376

We have discovered the following issue in our effort to migrate to Magnolia 5.4.7:

We are switching to light development, and now have definitions in YAML stored in the resources workspace.

On the sites that use YAML definitions, we have observed that we sometimes get exceptions to do with stale sessions. Two sample stack traces are included below.
The problem is hard to reproduce, you have to open the site in the editor, and "click around" for a while. It seems to occur more frequently under load.
The problem occurs frequently enough that will prevent our release (scheduled for Tue next week) to production.

The problem occurs because the definition is checked for modifications, and the getLastModified() call on the resource attempts to load the lastModified information from JCR, and encounters a stale session.

The confusing part for me is that the JCRResource code actually checks for stale sessions and (theoretically) refreshes the node if needed.
(See: info.magnolia.resourceloader.jcr.JcrResource.getNode() line 63 )

What is going on here?

Stack trace 1:

Caused by: javax.jcr.RepositoryException: This session has been closed. See the chained exception for a trace of where the session was closed.
        at org.apache.jackrabbit.core.session.SessionState.checkAlive(SessionState.java:150)
        at org.apache.jackrabbit.core.ItemImpl.sanityCheck(ItemImpl.java:101)
        at org.apache.jackrabbit.core.NodeImpl.hasProperty(NodeImpl.java:2456)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.util.NodeTypes$Created.getCreated(NodeTypes.java:218)
        at info.magnolia.jcr.util.NodeTypes$LastModified.getLastModified(NodeTypes.java:86)
        at info.magnolia.resourceloader.jcr.JcrResourceOrigin.getLastModified(JcrResourceOrigin.java:178)
        at info.magnolia.resourceloader.jcr.JcrResourceOrigin.getLastModified(JcrResourceOrigin.java:90)
        at info.magnolia.resourceloader.AbstractResource.getLastModified(AbstractResource.java:89)
        at info.magnolia.resourceloader.layered.LayeredResourceOrigin.getLastModified(LayeredResourceOrigin.java:148)
        at info.magnolia.resourceloader.layered.LayeredResourceOrigin.getLastModified(LayeredResourceOrigin.java:73)
        at info.magnolia.resourceloader.AbstractResource.getLastModified(AbstractResource.java:89)
        at org.mgnlconfig.yaml.dependency.YamlFileConfigDependency.needsUpdate(YamlFileConfigDependency.java:64)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider$1.apply(YamlConfigurationDataProvider.java:73)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider$1.apply(YamlConfigurationDataProvider.java:70)
        at com.google.common.collect.Iterators$7.computeNext(Iterators.java:652)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
        at com.google.common.collect.Iterators.tryFind(Iterators.java:752)
        at com.google.common.collect.Iterables.tryFind(Iterables.java:675)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider.needsUpdate(YamlConfigurationDataProvider.java:70)
        at org.mgnlconfig.YamlDefinitionProvider.refreshYamlData(YamlDefinitionProvider.java:100)
        at org.mgnlconfig.YamlDefinitionProvider.get(YamlDefinitionProvider.java:76)
        at info.magnolia.config.registry.AbstractDefinitionProviderWrapper.get(AbstractDefinitionProviderWrapper.java:60)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry$1.get(TemplateDefinitionRegistry.java:133)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry$1.get(TemplateDefinitionRegistry.java:130)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry.getTemplateDefinition(TemplateDefinitionRegistry.java:118)
        at info.magnolia.rendering.template.assignment.MetaDataBasedTemplateDefinitionAssignment.getAssignedTemplateDefinition(MetaDataBasedTemplateDefinitionAssignment.java:100)
        at at.lfrz.magnolia.jcr.predicate.TemplateParameterPredicate.evaluateTyped(TemplateParameterPredicate.java:33)
        at at.lfrz.magnolia.jcr.predicate.TemplateParameterPredicate.evaluateTyped(TemplateParameterPredicate.java:13)
        at at.lfrz.magnolia.jcr.predicate.AndPredicate.evaluateTyped(AndPredicate.java:35)
        at at.lfrz.magnolia.jcr.predicate.XorPredicate.evaluateTyped(XorPredicate.java:22)
        at at.lfrz.magnolia.jcr.predicate.AndPredicate.evaluateTyped(AndPredicate.java:35)
        at info.magnolia.jcr.predicate.AbstractPredicate.evaluate(AbstractPredicate.java:49)
        at org.apache.jackrabbit.commons.iterator.FilteringNodeIterator.seekNext(FilteringNodeIterator.java:114)
        at org.apache.jackrabbit.commons.iterator.FilteringNodeIterator.<init>(FilteringNodeIterator.java:42)
        at info.magnolia.jcr.util.NodeUtil.getNodes(NodeUtil.java:668)
        at at.lfrz.magnolia.atk.templating.ContentListing.buildListing(ContentListing.java:433)
        at at.lfrz.magnolia.atk.templating.ContentListing.getListing(ContentListing.java:217)
        at at.lfrz.magnolia.atk.templating.ATKAbstractModelBase.getListing(ATKAbstractModelBase.java:82)
        at sun.reflect.GeneratedMethodAccessor810.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at freemarker.ext.beans.BeansWrapper.invokeMethod(BeansWrapper.java:1385)
        at freemarker.ext.beans.ReflectionCallableMemberDescriptor.invokeMethod(ReflectionCallableMemberDescriptor.java:52)
        at freemarker.ext.beans.MemberAndArguments.invokeMethod(MemberAndArguments.java:48)
        at freemarker.ext.beans.OverloadedMethodsModel.exec(OverloadedMethodsModel.java:62)
        ... 183 more
Caused by: java.lang.Exception: Stack trace of  where session-admin-68869 was originally closed
        at org.apache.jackrabbit.core.session.SessionState.close(SessionState.java:275)
        at org.apache.jackrabbit.core.SessionImpl.logout(SessionImpl.java:943)
        at org.apache.jackrabbit.core.XASessionImpl.logout(XASessionImpl.java:394)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.repository.mbean.TrackingSessionWrapper.logout(TrackingSessionWrapper.java:57)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.context.AbstractRepositoryStrategy.releaseSession(AbstractRepositoryStrategy.java:99)
        at info.magnolia.context.AbstractRepositoryStrategy.release(AbstractRepositoryStrategy.java:87)
        at info.magnolia.context.SystemRepositoryStrategy.release(SystemRepositoryStrategy.java:59)
        at info.magnolia.context.JCRSessionPerThreadSystemContext.releaseThread(JCRSessionPerThreadSystemContext.java:58)
        at info.magnolia.context.MgnlContext.release(MgnlContext.java:631)
        at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:131)
        ... 25 more

Stack trace 2:

ERROR  info.magnolia.rendering.engine.RenderingFilter 19.07.2016 10:45:57 -- This session has been closed. See the chained exception for a trace of where the session was closed.
javax.jcr.RepositoryException: This session has been closed. See the chained exception for a trace of where the session was closed.
        at org.apache.jackrabbit.core.session.SessionState.checkAlive(SessionState.java:150)
        at org.apache.jackrabbit.core.ItemImpl.sanityCheck(ItemImpl.java:101)
        at org.apache.jackrabbit.core.NodeImpl.hasProperty(NodeImpl.java:2456)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.util.NodeTypes$Created.getCreated(NodeTypes.java:218)
        at info.magnolia.jcr.util.NodeTypes$LastModified.getLastModified(NodeTypes.java:86)
        at info.magnolia.resourceloader.jcr.JcrResourceOrigin.getLastModified(JcrResourceOrigin.java:178)
        at info.magnolia.resourceloader.jcr.JcrResourceOrigin.getLastModified(JcrResourceOrigin.java:90)
        at info.magnolia.resourceloader.AbstractResource.getLastModified(AbstractResource.java:89)
        at info.magnolia.resourceloader.layered.LayeredResourceOrigin.getLastModified(LayeredResourceOrigin.java:148)
        at info.magnolia.resourceloader.layered.LayeredResourceOrigin.getLastModified(LayeredResourceOrigin.java:73)
        at info.magnolia.resourceloader.AbstractResource.getLastModified(AbstractResource.java:89)
        at org.mgnlconfig.yaml.dependency.YamlFileConfigDependency.needsUpdate(YamlFileConfigDependency.java:64)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider$1.apply(YamlConfigurationDataProvider.java:73)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider$1.apply(YamlConfigurationDataProvider.java:70)
        at com.google.common.collect.Iterators$7.computeNext(Iterators.java:652)
        at com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143)
        at com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138)
        at com.google.common.collect.Iterators.tryFind(Iterators.java:752)
        at com.google.common.collect.Iterables.tryFind(Iterables.java:675)
        at org.mgnlconfig.yaml.YamlConfigurationDataProvider.needsUpdate(YamlConfigurationDataProvider.java:70)
        at org.mgnlconfig.YamlDefinitionProvider.refreshYamlData(YamlDefinitionProvider.java:100)
        at org.mgnlconfig.YamlDefinitionProvider.get(YamlDefinitionProvider.java:76)
        at info.magnolia.config.registry.AbstractDefinitionProviderWrapper.get(AbstractDefinitionProviderWrapper.java:60)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry$1.get(TemplateDefinitionRegistry.java:133)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry$1.get(TemplateDefinitionRegistry.java:130)
        at info.magnolia.rendering.template.registry.TemplateDefinitionRegistry.getTemplateDefinition(TemplateDefinitionRegistry.java:118)
        at info.magnolia.rendering.engine.RenderingFilter.render(RenderingFilter.java:185)
        at info.magnolia.rendering.engine.RenderingFilter.handleTemplateRequest(RenderingFilter.java:140)
        at info.magnolia.rendering.engine.RenderingFilter.doFilter(RenderingFilter.java:94)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.rendering.model.ModelExecutionFilter.doFilter(ModelExecutionFilter.java:109)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.AggregatorFilter.doFilter(AggregatorFilter.java:100)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.security.BaseSecurityFilter.doFilter(BaseSecurityFilter.java:57)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.RepositoryMappingFilter.doFilter(RepositoryMappingFilter.java:108)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:74)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.VirtualUriFilter.doFilter(VirtualUriFilter.java:69)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.module.cache.executor.Bypass.processCacheRequest(Bypass.java:58)
        at info.magnolia.module.cache.executor.CompositeExecutor.processCacheRequest(CompositeExecutor.java:67)
        at info.magnolia.module.cache.filter.CacheFilter.doFilter(CacheFilter.java:174)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.i18n.I18nContentSupportFilter.doFilter(I18nContentSupportFilter.java:74)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.RangeSupportFilter.doFilter(RangeSupportFilter.java:84)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.security.BaseSecurityFilter.doFilter(BaseSecurityFilter.java:57)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.multisite.filters.CrossSiteSecurityFilter.doFilter(CrossSiteSecurityFilter.java:104)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.security.SecurityCallbackFilter.doFilter(SecurityCallbackFilter.java:79)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.security.LogoutFilter.doFilter(LogoutFilter.java:94)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.module.site.filters.SiteMergeFilter.doFilter(SiteMergeFilter.java:119)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at at.lfrz.magnolia.atk.errorpages.ATKMultiSiteFilter.doFilter(ATKMultiSiteFilter.java:138)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MultiChannelFilter.doFilter(MultiChannelFilter.java:83)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.module.cache.filter.GZipFilter.doFilter(GZipFilter.java:73)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at at.lfrz.magnolia.atk.filter.ImprovedLoggingFilter.doFilter(ImprovedLoggingFilter.java:77)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.security.auth.login.LoginFilter.doFilter(LoginFilter.java:127)
       at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.enterprise.registration.RegistrationFilter.doFilter(RegistrationFilter.java:64)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.CosMultipartRequestFilter.doFilter(CosMultipartRequestFilter.java:87)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.module.devicedetection.filter.DeviceDetectionFilter.doFilter(DeviceDetectionFilter.java:71)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.personalization.preview.filter.PreviewFilter.doFilter(PreviewFilter.java:92)
        at info.magnolia.cms.filters.OncePerRequestAbstractMgnlFilter.doFilter(OncePerRequestAbstractMgnlFilter.java:59)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.personalization.trait.AbstractTraitDetectorFilter.doFilter(AbstractTraitDetectorFilter.java:74)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.personalization.trait.AbstractTraitDetectorFilter.doFilter(AbstractTraitDetectorFilter.java:74)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.personalization.trait.AbstractTraitDetectorFilter.doFilter(AbstractTraitDetectorFilter.java:74)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.personalization.trait.AbstractTraitDetectorFilter.doFilter(AbstractTraitDetectorFilter.java:74)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.ContentTypeFilter.doFilter(ContentTypeFilter.java:148)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:74)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:81)
        at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at at.lfrz.magnolia.atk.filter.ImprovedLoggingFilter.doFilter(ImprovedLoggingFilter.java:77)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:128)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.MgnlFilterChain.doFilter(MgnlFilterChain.java:79)
        at info.magnolia.cms.filters.CompositeFilter.doFilter(CompositeFilter.java:65)
        at info.magnolia.cms.filters.AbstractMgnlFilter.doFilter(AbstractMgnlFilter.java:85)
        at info.magnolia.cms.filters.SafeDestroyMgnlFilterWrapper.doFilter(SafeDestroyMgnlFilterWrapper.java:107)
        at info.magnolia.cms.filters.MgnlFilterDispatcher.doDispatch(MgnlFilterDispatcher.java:67)
        at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:108)
        at info.magnolia.cms.filters.MgnlMainFilter.doFilter(MgnlMainFilter.java:94)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at at.lfrz.net.tomcat.valve.LFRZAccessLogValve.invoke(LFRZAccessLogValve.java:460)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1078)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.Exception: Stack trace of  where session-admin-17501 was originally closed
        at org.apache.jackrabbit.core.session.SessionState.close(SessionState.java:275)
        at org.apache.jackrabbit.core.SessionImpl.logout(SessionImpl.java:943)
        at org.apache.jackrabbit.core.XASessionImpl.logout(XASessionImpl.java:394)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.repository.mbean.TrackingSessionWrapper.logout(TrackingSessionWrapper.java:57)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.jcr.wrapper.DelegateSessionWrapper.logout(DelegateSessionWrapper.java:262)
        at info.magnolia.context.AbstractRepositoryStrategy.releaseSession(AbstractRepositoryStrategy.java:99)
        at info.magnolia.context.AbstractRepositoryStrategy.release(AbstractRepositoryStrategy.java:87)
        at info.magnolia.context.SystemRepositoryStrategy.release(SystemRepositoryStrategy.java:59)
        at info.magnolia.context.JCRSessionPerThreadSystemContext.releaseThread(JCRSessionPerThreadSystemContext.java:58)
        at info.magnolia.context.MgnlContext.release(MgnlContext.java:631)
        at info.magnolia.cms.filters.ContextFilter.doFilter(ContextFilter.java:131)
        ... 25 more

Analysis:

I have been looking at the code, and thinking about this problem.

If you follow the code in the stack-trace, I think it gets interesting around the call to JcrResourceOrigin.getLastModified(JcrResource).
This looks like this:

    @Override
    @SneakyThrows(RepositoryException.class)
    protected long getLastModified(JcrResource resource) {
        // TODO Compare: return resource.getNode().getProperty(JcrConstants.JCR_LASTMODIFIED)
        final Calendar lastModified = NodeTypes.LastModified.getLastModified(resource.getNode());
        if (lastModified == null) {
            // TODO: shouldn't this happen in info.magnolia.jcr.util.NodeTypes.LastModified.getLastModified() ?
            throw new RepositoryException("No lastModified or created date property on " + resource.getNode());
        }
        return lastModified.getTimeInMillis();
    }

Note that is calls resource.getNode(). The method JcrResource.getNode() looks like this:

    @SneakyThrows(RepositoryException.class)
    Node getNode() {
        if (!node.getSession().isLive()) {
            this.node = ((JcrResourceOrigin)getOrigin()).getJcrSession().getNodeByIdentifier(this.uuid);
        }

        return node;
    }

So it performs a session check on the node before returning it.

The returned node is then passed to NodeTypes.LastModified.getLastModified(Node), which via a few more calls then results in the session closed RepositoryException:

Caused by: javax.jcr.RepositoryException: This session has been closed. See the chained exception for a trace of where the session was closed.
        at org.apache.jackrabbit.core.session.SessionState.checkAlive(SessionState.java:150)
        at org.apache.jackrabbit.core.ItemImpl.sanityCheck(ItemImpl.java:101)
        at org.apache.jackrabbit.core.NodeImpl.hasProperty(NodeImpl.java:2456)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.wrapper.DelegateNodeWrapper.hasProperty(DelegateNodeWrapper.java:304)
        at info.magnolia.jcr.util.NodeTypes$Created.getCreated(NodeTypes.java:218)
        at info.magnolia.jcr.util.NodeTypes$LastModified.getLastModified(NodeTypes.java:86)
        at info.magnolia.resourceloader.jcr.JcrResourceOrigin.getLastModified(JcrResourceOrigin.java:178)

So in-between the session-check performed by JcrResource.getNode() and the one done in SessionState.checkAlive(), the session is being closed.

This makes sense also when we consider that the error occurs when we "click around quickly", causing concurrent requests.

The problem is made visible by our use of the light-yaml module, because the module causes a lot of JCR resource access when refreshing the YAML definitions, but it is not caused by that module.

Rather, I think the problem is in the design of the new (JCR) resources layer:

If you think about the code, and the way magnolia works, I think we have a clear race condition happening here. JcrResource.getNode() returns a cached node after checking its session. So you're relying on the session being alive after the call to JcrResource.getNode(), but the session-check and the subsequent use of the node object are not in a synchronized block.

IMHO it is a fundamental design error to store any JCR node object in a field of an object that has application or session scope. A node object always only has validity within a JcrSession, and in magnolia the JcrSessions are opened/closed with the requests. Trying to cache nodes across requests doesn't work.

So, if my analysis is correct, I see two potential fixes:

1. Get the node fresh for each call to JcrResource.getNode()
2. Or, make the session check more sophisticated by not only checking that the session is active, but that it is in fact the same session as that of the current request.

Regards from Vienna,

Richard



 Comments   
Comment by Richard Unger [ 22/Jul/16 ]

I also have a potential fix for this at:

https://runger@git.magnolia-cms.com/scm/~runger/main.git

in the branch SUPPORT-6376

We will be testing this patch today, and will let you know how it works for us.

Should I create a pull request for that? Who would I send it to?

Comment by Richard Unger [ 22/Jul/16 ]

We have installed the patched version of the resourceloader module in our QS system, and now we can no longer reproduce the bug.
We will observe to see if there are other issues, but for the moment it looks good.

Do you want a pull request?

Comment by Marcus Büttner [ 09/Feb/17 ]

Is there a way to fix it asap? It's a little bit annoying to patch it again and again with every magnolia upgrade. For more than seven month there exists a patch which works.

Comment by Richard Unger [ 08/Mar/17 ]

Agreed with Marcus. Please note that this is a fairly nasty issue, very easily fixed, and there is a support ticket waiting for bugfix release open since many months...

Comment by Jan Haderka [ 08/Mar/17 ]

From what I can see in the stacktraces session was in both cases closed correctly once the processing of the request was finished. By that time all the rendering is/should be already done and no further access to the nodes should be made by any code.
The fact that it happens suggests that either your code or that of light-yaml uses some sort of caching and attempts to access node that should no longer be available which is something that never was supported in the first place.

Comment by Mikaël Geljić [ 08/Mar/17 ]

had Resource reload happens in the JCR observation thread; there's no explicit Context#release or logout there, afaict.

Resource-change events are dispatched synchronously within that thread—which for configuration sources triggers a reload of the definition. JCR resource origin gets the session from system context. I can imagine contention over that one, as it may be accessed from other threads.

TBH, I'm surprised the stack-trace shows system context is the one being closed in ContextFilter, instead of a plain WebContext. There could be something else at play, "upgrading" current MgnlContext instance to system-context, and forgetting to set it back. Or do we have legit cases for this? —would back the contention nonetheless.

Re: proposed fix
I'd support removing the Node reference inside JcrResource objects (as runger mentioned); I also can't see why not picking up the minimal proposed patch in a PR, given its real-life record. Just saying it might just hide the underlying issue.

Comment by Richard Unger [ 10/Mar/17 ]

Please don't close this without fixing. The associated support issue is still open, and we do expect a fix.

Contrary to what Jan writes, it is an actual bug in magnolia (it's not that hard to follow in the code, JcrResource keeps a node reference around which goes stale and does not check it before using it again).

Comment by Mikaël Geljić [ 17/Mar/17 ]

Hi Richard,

TL;DR The bug only manifests itself because of the light-yaml module, precisely because YamlConfigurationDataProvider keeps hard-refs to JcrResources.

This is otherwise not the case in the product—and I tried hard to prove otherwise. Each request gets a brand new JcrResource associated to its own node within current session/thread, and those resources are as much throwaway as the node itself.

I don't debate JcrResource#getNode is error-prone, and upon short discussion should be fixed by using LazyNodeWrapper or SystemNodeWrapper. Any chance you can test if that does the trick as well for you?

I'm asking because, for your information, YAML extends are being productized (MAGNOLIA-6664), so it's seemingly not long until the product is affected as well... If the problem does occur there, then no doubt this will be a prerequisite task.

Now about light-yaml itself, I consider it as much a questionable choice to ping the registries and potentially refresh template defs upon rendering. I'm less bothered for dialog defs as they're not public-facing, though I can't see why they wouldn't suffer the same trouble here.
We can debate whether this was hijacked usage of resources, but as a forge module it certainly did not guarantee the same quality nor amount of testing that would otherwise have revealed this issue before.
Honestly, that's the grief I personally have against evangelizing individuals' approaches on corporate channels; especially since this light-yaml module coordinates encouraged confusion (org.mgnlconfig).

I'll ask the guys to specifically verify it in the scope of MAGNOLIA-6664; shouldn't stay closed for too long...

Cheers,
Mika

Generated at Mon Feb 12 04:17:17 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.