spring-mvctomcat7out-of-memorylog4j2hotdeploy

OutOfMemoryError when hot-deploying SpringMVC app to Tomcat7 - possible relation to log4j2


I am having trouble Hot Deploying a Spring-MVC 4.0 (not SpringBoot) Web Application. I am trying to go xml-less and just use JavaConfig. OutOfMemoryErrors result when I remove web.xml, or when I deploy an empty web.xml with nothing but an empty element. This does not happen every time the app is hot-deployed, and after a successful hot-deployment, the app does work correctly, but after three or four hot-deployments with this configuration the following error occurs:

Jul 03, 2015 10:49:43 AM org.springframework.web.context.ContextLoader initWebApplicationContext
    SEVERE: Context initialization failed
    java.lang.OutOfMemoryError: PermGen space
            at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:547)
            at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
            at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303)
            at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
            at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
            at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:199)
            at org.springframework.context.support.PostProcessorRegistrationDelegate.registerBeanPostProcessors(PostProcessorRegistrationDelegate.java:220)
            at org.springframework.context.support.AbstractApplicationContext.registerBeanPostProcessors(AbstractApplicationContext.java:615)
            at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:465)
            at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:403)
            at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
            at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
            at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:5014)
            at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5524)
            at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
            at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:901)
            at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:877)
            at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:649)
            at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:1081)
            at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1877)
            at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
            at java.util.concurrent.FutureTask.run(FutureTask.java:262)
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
            at java.lang.Thread.run(Thread.java:745)

    Jul 03, 2015 10:49:44 AM org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor run
    SEVERE: Unexpected death of background thread ContainerBackgroundProcessor[StandardEngine[Catalina]]
    java.lang.OutOfMemoryError: PermGen space
            at java.util.concurrent.FutureTask.report(FutureTask.java:122)
            at java.util.concurrent.FutureTask.get(FutureTask.java:188)
            at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:816)
            at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:488)
            at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1655)
            at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:328)
            at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
            at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
            at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1374)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1546)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1556)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1524)
            at java.lang.Thread.run(Thread.java:745)

    Exception in thread "ContainerBackgroundProcessor[StandardEngine[Catalina]]" java.lang.OutOfMemoryError: PermGen space
            at java.util.concurrent.FutureTask.report(FutureTask.java:122)
            at java.util.concurrent.FutureTask.get(FutureTask.java:188)
            at org.apache.catalina.startup.HostConfig.deployWARs(HostConfig.java:816)
            at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:488)
            at org.apache.catalina.startup.HostConfig.check(HostConfig.java:1655)
            at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:328)
            at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:117)
            at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:90)
            at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1374)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1546)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1556)
            at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1524)
            at java.lang.Thread.run(Thread.java:745)

Evidently memory is leaking with this configuration somehow.

It may or may not be relevant that this web application uses Log4j2. An earlier Stack Overflow question explored this. If the web application uses just the following minimal web.xml

<?xml version="1.0"?>
<web-app xmlns="http://java.sun.com/xml/ns/javaee"
          xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
          xsi:schemaLocation="http://java.sun.com/xml/ns/javaee 
          http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
          version="3.0">

    <context-param>
        <param-name>log4jConfiguration</param-name>
        <param-value>file:///path/to/log4j2.xml</param-value>
    </context-param> 

</web-app>

then the WebApp can be hot-deployed over and over without getting these errors.

Can anyone hazard a guess at what could be going on here?

Update: - See the discussion between @Makoton and myself below. It appears that there may well be a Garbage collection issue relating to loading log4j2 from the application (the Java Config way) vs loading it from web.xml (the traditional way). See this article which debunks the "classic" Stack Overflow suggestion for this problem (similar to that cited by Makoton).

This makes me think about SpringBoot, which, as I understand it, loads Tomcat as part of the application. This might be one solution to this problem.


Solution

  • I believe Luke is right that this issue may be caused by a bug in Log4j2.

    The bug is that if the <display-name> element is not present in the web.xml, the Log4jServletContextListener class responsible for log4j resource management can only start, but not stop log4j.

    This means that no cleanup happens when the web application is stopped or restarted. JMX MBeans are not unregistered, but also any threads are not stopped, and as a result Log4j classes are not unloaded. The leaked memory grows every time the web app is restarted, because each web app has its own classloader (so the VM sees them as different classes).

    This bug is fixed in Git master now and the fix will be part of the log4j 2.5 release. Meanwhile, please use a <display-name> element in your web.xml.