Log4j2自定义Hibernate Appender内存泄漏及JDBC日志配置问题

Background #

We migrated our application from a self-developed logging component to Log4j2, with the largest deployment environment running ~60,000 tasks daily. We built a custom InnovaIntegrationsportalHibernateAppender based on Hibernate to write logs directly to the database. After roughly 36 hours of runtime, the JVM crashed with an OutOfMemoryError (OOME). Analyzing the hprof heap dump revealed that org.apache.logging.log4j.core.appender.AbstractManager was consuming 763.5MB of memory, pointing to a suspected memory leak. We created a ProfilingTest class to reliably reproduce this issue.

Update (May 2, 2019) #

After switching to Log4j2's built-in JDBC logging component and migrating to a different database, initial tests ran without issues. However, when dynamically adding a FileAppender and linking it to the JDBC Appender's Logger defined in our XML configuration, we hit two new problems:

• The generated log file remains completely empty
• No log entries are written to the database
  We've put together a test project to replicate this scenario.

InnovaIntegrationsportalHibernateAppender Code #

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;
    }

    @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);
        } finally {
            try {
                if (em != null) {
                    em.close();
                }
            } catch (Throwable t) {
                LOGGER.error("Cant close em: ", t);
            }
        }
    }

    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;
        }
    }
}

ProfilingTest Code #

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();
    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();
            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);
            Appender appender = InnovaIntegrationsportalHibernateAppender.createAppender(laufid, null, null, "LISA_4711", "LI0001", laufid);
            appender.start();
            AppenderRef ref = AppenderRef.createAppenderRef(laufid, Level.ALL, null);
            AppenderRef refFull = AppenderRef.createAppenderRef(laufid + "FULL", Level.ALL, null);
            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);
            loggerConfig.addAppender(fullAppender, Level.ALL, null);
            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");
    }
}

内容的提问来源于stack exchange，提问作者Stefan Höltker