[MAGNOLIA-8362] Add debug logging for tracking SystemRepositoryStrategy instances Created: 25/Mar/22  Updated: 15/Apr/22  Resolved: 29/Mar/22

Status: Closed
Project: Magnolia
Component/s: core
Affects Version/s: None
Fix Version/s: 6.2.18

Type: Improvement Priority: Neutral
Reporter: Michael Duerig Assignee: Michael Duerig
Resolution: Done Votes: 0
Labels: foundation_team
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Cloners
is cloned by MAGNOLIA-8380 CLONE - Add debug logging for trackin... Closed
Issue split
split from MGNLEE-645 Cannot stop Magnolia since tomcat upg... Closed
Template:
Acceptance criteria:
Empty
Task DoD:
[X]* Doc/release notes changes? Comment present?
[X]* Downstream builds green?
[X]* Solution information and context easily available?
[X]* Tests
[X]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Release notes required:
Yes
Date of First Response:

 Description   

MGNLEE-645 reported a thread local leak of SystemRepositoryStrategy instances on shutdown:

org.apache.catalina.loader.WebappClassLoaderBase.checkThreadLocalMapForLeaks The web application [magnoliaAuthor] created a ThreadLocal with key of type [java.lang.ThreadLocal] (value [java.lang.ThreadLocal@7d3d101b]) 
and a value of type [info.magnolia.context.SystemRepositoryStrategy] (value [info.magnolia.context.SystemRepositoryStrategy@5cdec700]) but failed to remove it when the web application was stopped. Threads are going to be renewed over time to try and avoid a probable memory leak.

So far we were not able to reliably reproduce the problem.

For making it easier to diagnose the problem we should implement additional logging to make above warning more helpful. Instead of logging SystemRepositoryStrategy@5cdec700 we should log the stack trace from the time the affected SystemRepositoryStrategy instance was created.



 Comments   
Comment by Michael Duerig [ 25/Mar/22 ]

Implemented solution

When WebappClassLoaderBase.checkThreadLocalMapForLeaks() detects a leaked SystemRepositoryStrategy instance it now logs it as

SystemRepositoryStrategy[No creation stack trace available. Enable DEBUG logging for class info.magnolia.context.SystemRepositoryStrategy to enable it.]

indicating that enabling debug logging for info.magnolia.context.SystemRepositoryStrategy helps to collect the stack traces for where those leaked instances have been created. With debug logging enabled SystemRepositoryStrategy instances are logged as

SystemRepositoryStrategy[Creation stack trace =[info.magnolia.context.SystemRepositoryStrategy.<init>(SystemRepositoryStrategy.java:64), sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method), sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62), sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45), java.lang.reflect.Constructor.newInstance(Constructor.java:423), info.magnolia.objectfactory.ObjectManufacturer.newInstance(ObjectManufacturer.java:129), info.magnolia.objectfactory.ObjectManufacturer.newInstance(ObjectManufacturer.java:99), info.magnolia.objectfactory.guice.GuiceComponentProvider.newInstanceWithParameterResolvers(GuiceComponentProvider.java:134), info.magnolia.objectfactory.guice.GuiceComponentProvider.newInstanceWithParameterResolvers(GuiceComponentProvider.java:120), info.magnolia.objectfactory.guice.GuiceComponentProvider.newInstance(GuiceComponentProvider.java:115), info.magnolia.objectfactory.Components.newInstance(Components.java:100), info.magnolia.context.JCRSessionPerThreadSystemContext.getRepositoryStrategy(JCRSessionPerThreadSystemContext.java:50), info.magnolia.context.AbstractContext.getJCRSession(AbstractContext.java:124), info.magnolia.module.groovy.support.classes.MgnlGroovyResourceLoader.loadGroovySourceFromRepository(MgnlGroovyResourceLoader.java:110), info.magnolia.module.groovy.support.classes.MgnlGroovyResourceLoader.loadGroovySource(MgnlGroovyResourceLoader.java:89), groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:906), groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:745), info.magnolia.module.groovy.support.classes.GroovyClassFactory.forName(GroovyClassFactory.java:99), info.magnolia.objectfactory.configuration.LegacyComponentsConfigurer.classForName(LegacyComponentsConfigurer.java:150), info.magnolia.objectfactory.configuration.LegacyComponentsConfigurer.addComponent(LegacyComponentsConfigurer.java:95), info.magnolia.objectfactory.configuration.LegacyComponentsConfigurer.doWithConfiguration(LegacyComponentsConfigurer.java:88), info.magnolia.objectfactory.guice.GuiceComponentProviderBuilder.build(GuiceComponentProviderBuilder.java:111), info.magnolia.objectfactory.guice.GuiceComponentProviderBuilder.build(GuiceComponentProviderBuilder.java:195), info.magnolia.cms.beans.config.ConfigLoader.load(ConfigLoader.java:142), info.magnolia.init.MagnoliaServletContextListener$1.doExec(MagnoliaServletContextListener.java:259), info.magnolia.context.MgnlContext$VoidOp.exec(MgnlContext.java:407), info.magnolia.context.MgnlContext$VoidOp.exec(MgnlContext.java:404), info.magnolia.context.MgnlContext.doInSystemContext(MgnlContext.java:378), info.magnolia.init.MagnoliaServletContextListener.startServer(MagnoliaServletContextListener.java:256), info.magnolia.init.MagnoliaServletContextListener.contextInitialized(MagnoliaServletContextListener.java:182), info.magnolia.init.MagnoliaServletContextListener.contextInitialized(MagnoliaServletContextListener.java:128), org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4643), org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5109), org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:183), org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:742), org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:718), org.apache.catalina.core.StandardHost.addChild(StandardHost.java:703), org.apache.catalina.startup.HostConfig.manageApp(HostConfig.java:1737), sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method), sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62), sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43), java.lang.reflect.Method.invoke(Method.java:498), org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:287), com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819), com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801), org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:457), org.apache.catalina.mbeans.MBeanFactory.createStandardContext(MBeanFactory.java:406), sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method), sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62), sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43), java.lang.reflect.Method.invoke(Method.java:498), org.apache.tomcat.util.modeler.BaseModelMBean.invoke(BaseModelMBean.java:287), com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819), com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801), com.sun.jmx.remote.security.MBeanServerAccessController.invoke(MBeanServerAccessController.java:468), javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468), javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76), javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309), java.security.AccessController.doPrivileged(Native Method), javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1408), javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829), sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method), sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62), sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43), java.lang.reflect.Method.invoke(Method.java:498), sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357), sun.rmi.transport.Transport$1.run(Transport.java:200), sun.rmi.transport.Transport$1.run(Transport.java:197), java.security.AccessController.doPrivileged(Native Method), sun.rmi.transport.Transport.serviceCall(Transport.java:196), sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573), sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834), sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688), java.security.AccessController.doPrivileged(Native Method), sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687), java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149), java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624), java.lang.Thread.run(Thread.java:748)]]
Comment by Roman Kovařík [ 28/Mar/22 ]

Could we forward-port this to 6.3?

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