Memory leak with Log4j2 custom Hibernate Appender

Question

We moved our application from a own small logging component to Log4j2. The application runs about 60.000 jobs per day at our biggest installation.

We write our own Appender which writes using Hibernate to our DB (see InnovaIntegrationsportalHibernateAppender).

After a runtime of ~36h the JVM crashed with Out of Memory Exception/Error(OOME), analysing the hprof i saw that there is a amount of 763,5MB of the class org.apache.logging.log4j.core.appender.AbstractManager

see screenshot of the Analyse attached (2019-04-12 13_20_45-eclips...)

https://issues.apache.org/jira/browse/LOG4J2-2589

Going deeper i tried to reconstruct the behavior in a test class and profiled its result (see screenshot-1).

Looks like a memory leak to me.

InnovaIntegrationsportalHibernateAppender

package de.itout.innova.log4j.innova_log4j_appender;

import de.itout.innova.ssp.entities.ssp.entities.*;
import de.itout.jpa.util.*;
import java.io.*;
import java.util.*;
import javax.persistence.*;
import org.apache.logging.log4j.core.*;
import org.apache.logging.log4j.core.appender.*;
import org.apache.logging.log4j.core.config.plugins.*;
import org.apache.logging.log4j.core.layout.*;

/**
 *
 * @author swendelmann
 */
@Plugin(name = "InnovaIntegrationsportalHibernateAppender", category = "Core", elementType = "appender")
public class InnovaIntegrationsportalHibernateAppender extends AbstractAppender
{

  private String schnittstelle;
  private String version;
  private String laufId;
  private EntityManager em;

  public InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout)
  {
    super(name, filter, layout);
  }

  public InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions)
  {
    super(name, filter, layout, ignoreExceptions);
  }

  private InnovaIntegrationsportalHibernateAppender(String name, Filter filter, Layout<? extends Serializable> layout, boolean ignoreExceptions, String schnittstelle, String version, String laufId)
  {
    super(name, filter, layout, ignoreExceptions);
    this.schnittstelle = schnittstelle;
    this.version = version;
    this.laufId = laufId;
  }

  // Your custom appender needs to declare a factory method
  // annotated with `@PluginFactory`. Log4j will parse the configuration
  // and call this factory method to construct an appender instance with
  // the configured attributes.
  @PluginFactory
  public static InnovaIntegrationsportalHibernateAppender createAppender(
          @PluginAttribute("name") String name,
          @PluginElement("Layout") Layout<? extends Serializable> layout,
          @PluginElement("Filter") final Filter filter,
          @PluginAttribute("schnittstelle") String schnittstelle,
          @PluginAttribute("version") String version,
          @PluginAttribute("laufId") String laufId
  )
  {
    if (name == null)
    {
      LOGGER.error("No name provided for InnovaIntegrationsportalHibernateAppender");
      return null;
    }
    if (layout == null)
    {
      layout = PatternLayout.createDefaultLayout();
    }
    if (laufId == null || laufId.isEmpty())
    {
      LOGGER.error("No laufid provided for InnovaIntegrationsportalHibernateAppender");
    }
    return new InnovaIntegrationsportalHibernateAppender(name, filter, layout, true, schnittstelle, version, laufId);
  }

  @Override
  public void append(LogEvent event)
  {
    try
    {

      em = JPAUtil.getEntityManager("SSP");
      em.getTransaction().begin();
      LauflogPK lauflogPK = new LauflogPK(schnittstelle, version, laufId, getNextLaufLogPos());
      Lauflog lauflog = new Lauflog(lauflogPK);
      lauflog.setLevel(event.getLevel().name());
      Date eventDateTime = new Date(event.getTimeMillis());
      lauflog.setLastchangeAenderungsdatum(eventDateTime);
      lauflog.setLastchangeAenderungszeit(eventDateTime);
      lauflog.setLastchangeBenutzer("WENDELMANN");
      lauflog.setLastchangeLogflag('A');
      lauflog.setText(event.getMessage().getFormattedMessage());
      em.persist(lauflog);
      em.getTransaction().commit();
    }
    catch (Throwable t)
    {
      em.getTransaction().rollback();
      LOGGER.error("Cant commit to Database InnovaIntegrationsportalHibernateAppender ", t);
      //TODO Log to file
    }
    finally
    {
      try
      {
        if (em != null)
        {
          em.close();
        }
      }
      catch (Throwable t)
      {
        LOGGER.error("Cant close em: ", t);
      }
    }

  }

  /**
   * SELECT ISNULL(MAX(POS)+1,0) FROM LAUFLOG
   * @return 
   */
  private int getNextLaufLogPos()
  {
    Integer i = (Integer) em.createQuery("SELECT MAX(l.lauflogPK.pos)+1 FROM Lauflog l WHERE l.lauflogPK.schnittstelle = :schnittstelle AND l.lauflogPK.version = :version AND l.lauflogPK.lauf = :lauf ")
            .setParameter("schnittstelle", this.schnittstelle)
            .setParameter("version", this.version)
            .setParameter("lauf", this.laufId)
            .getSingleResult();
    if (i == null)
    {
      return 0;
    }
    else
    {
      return i;
    }
  }

}

package de.itout.innova.log4j;

import de.itout.innova.log4j.innova_log4j_appender.*;
import de.itout.jpa.util.*;
import java.io.*;
import java.nio.charset.*;
import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.*;
import org.apache.logging.log4j.core.appender.*;
import org.apache.logging.log4j.core.config.*;
import org.apache.logging.log4j.core.layout.*;
import org.junit.*;

/**
 *
 * @author swendelmann
 */
public class ProfilingTest
{

  QEntityManager em;
  private org.apache.logging.log4j.Logger logg = LogManager.getLogger();
  // Potential memory leak
  final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);

  public ProfilingTest()
  {
  }

  @Before
  public void setUp()
  {
    em = JPAUtil.getEntityManager("SSP");
  }

  @After
  public void tearDown()
  {
    em.close();
  }

  @Test
  public void testProfiling()
  {
    logg.trace("Start the Main Method");
    int runs = 1000;
    int logs = 10;
    String allSicherungsVerzeichnis = "target/sicherungsverzeichnis/";
    logg.debug("Start Test mit " + runs + " durchläufen");
    for (int i = 0; i < runs; i++)
    {
      String laufid = "LD0" + i;

      File laufLogFile = new File(allSicherungsVerzeichnis + laufid + "_full.log");

      Configuration config = ctx.getConfiguration();

      // Full File Logger
      Layout layout = PatternLayout.newBuilder()
        .withConfiguration(config)
        .withPattern(PatternLayout.SIMPLE_CONVERSION_PATTERN)
        .withCharset(Charset.forName("UTF-8"))
        .build();

      Appender fullAppender = FileAppender.newBuilder()
        .setConfiguration(config)
        .setName(laufid + "FULL")
        .withFileName(laufLogFile.getAbsolutePath())
        .withAppend(true)
        .withImmediateFlush(true)
        .setIgnoreExceptions(false)
        .setLayout(layout)
        .build();

      fullAppender.start();
      config.addAppender(fullAppender);

      // Hibernate Logger
      Appender appender = InnovaIntegrationsportalHibernateAppender.createAppender(laufid, null, null, "LISA_4711", "LI0001", laufid);

      appender.start();

      AppenderRef ref = AppenderRef.createAppenderRef(laufid, Level.ALL, null); // HIER LOGLEVEL DB EINSTELLEN
      AppenderRef refFull = AppenderRef.createAppenderRef(laufid + "FULL", Level.ALL, null); // HIER LOGLEVEL Datei einstellen
      AppenderRef[] refs = new AppenderRef[]
      {
        ref, refFull
      };

      LoggerConfig loggerConfig = LoggerConfig
        .createLogger(false, Level.ALL, laufid, "true", refs, null, config, null);
      loggerConfig.addAppender(appender, Level.ALL, null); // HIER LOGLEVEL ebenfalls einstellen
      loggerConfig.addAppender(fullAppender, Level.ALL, null); // HIER LOGLEVEL Datei einstellen
      config.addLogger(laufid, loggerConfig);

      ctx.updateLoggers();

      org.apache.logging.log4j.Logger log = LogManager.getLogger(laufid);

      for (int j = 0; j < logs; j++)
      {
        log.info("Ich bin nur eine Info und soll nur in das FullFile logging!");
        log.warn("Ich bin ein böser warning und soll in das FullFile und in das Innova Integrationsportal Hibernate Logging");
      }

      appender.stop();
      fullAppender.stop();

      config.removeLogger(laufid);
      config.removeLogger(laufid + "FULL");
      ctx.updateLoggers();
    }
    logg.trace("Fertig");
  }
}

Update 02.05.2019

I moved to the JDBC logger and changed the DB. The first test was about fine, but when i programatically add a fileappender + logger with ref to the fileappender & jdbc appender from xml config, i got empty files and no db entries.

I made up a test project on github see: https://github.com/stefanwendelmann/JavaLogging

Answer 1

I am looking at : https://github.com/stefanwendelmann/JavaLogging/blob/master/src/test/java/LoggerTest.java

I think this is what is happening:

private static final LoggerContext ctx ...

Configuration config = ctx.getConfiguration();

config.addAppender(fullAppender);

and you never remove it, so it keeps adding in the static field. You can debug and see what is inside Log4j2. I haven't debugged yet.

Memory leaks are coming through static fields and through classloaders usually.

Best option is to move away from logging with jdbc. It is designed to work in another way and not to dynamically add/remove appenders, because you have to do all the zookeeping of objects. It may be easier for you to just make a facade pattern and hide the complexity there and only expose couple of methods for write in DB.