OutOfMemoryException because WatchManager isn't garbage collected

[Yavor16]

Description

We are using file logging because we have many steps and after every step the logs are persisted in the database and the files are deleted. While our application was running on Java 11, we had no problems. When we switched to Java 17, the problems started. I used the GC logs, jcmd and jmap to find out that module/org.apache.logging.log4j.core.util.WatchManager is not garbage collected. Instead of unloading the WatchManager class, the logs are full with:

Dynamic nestmate: unnamed module/org.apache.logging.log4j.core.util.WatchManager$$Lambda$6426/0x00000007f2680228, nest_host org.apache.logging.log4j.core.util.WatchManager, is hidden LookupDefineClass: org/apache/logging/log4j/core/util/WatchManager$$Lambda$6427 - with dynamic nest-host org.apache.logging.log4j.core.util.WatchManager, hidden, strong, without vm annotation

We tried switching the GC-s but nothing worked. We tried different log4j versions. Now we use 2.23.1.

We've tried to stop/close everything.

FileUtils.deleteQuietly(log) loggerContext.stop(); loggerContext.getConfiguration().getAppenders().values().forEach(appender -> { loggerContext.getRootLogger().removeAppender(appender); appender.stop(); }); loggerContext.getConfiguration().getWatchManager().getConfigurationWatchers().keySet().forEach(key -> { loggerContext.getConfiguration().getWatchManager().unwatch(key); }); loggerContext.getConfiguration().getWatchManager().reset(); loggerContext.getConfiguration().getLoggers().values().forEach(AbstractLifeCycle::stop); loggerContext.getConfiguration().getLoggers().values().forEach(loggerConfig -> { loggerConfig.getAppenderRefs().clear(); }); loggerContext.getConfiguration().getWatchManager().stop(); loggerContext.getConfiguration().getWatchManager().getConfigurationWatchers().clear(); LogManager.shutdown();

We create new FileAppender, LoggerContext, LoggerConfig for every new log. LoggerContext loggerContext = new LoggerContext(loggerName); FileAppender fileAppender = FileAppender.newBuilder() .setName(loggerName) .withFileName(logFile.toString()) .setLayout(layoutCreatorFunction.apply(context)) .setConfiguration(context.getConfiguration()) .build(); fileAppender.start(); loggerContext.getConfiguration() .addAppender(fileAppender); LoggerConfig loggerConfig = loggerContext.getConfiguration() .getLoggerConfig(loggerName); Other config stuff loggerContext.updateLoggers();

[vy]

@Yavor16, could you provide a little bit more context, please?

• Could you share your Log4j configuration file, i.e., log4j2.xml?
• What kind of an application is this? JEE? Spring Boot? Which framework (incl. version)?
• Do you have multiple logger contexts?
• While in Java 11, were you starting and/or stopping Log4j programmatically?

Nests (the new access control context introduced in Java 11) can also be causing a problem. But before knocking the door of OpenJDK project, we better make sure to do our homework first.

[Yavor16]

@vy, yes, here is more information: We don't have configuration file. Our app mainly uses Spring + Flowable. The spring version is 5.3.34 and flowable 6.8.0. We generate new LoggerContext for every step, so we have multiple contexts. After a step is finished we save the log file in our base and close the context using loggerContext.stop();. In java 11 we were doing everything programmatically.

[vy]

Generating a new LoggerContext for every step... seems like pretty much overkill to me. Why do you do this? Why is simply using the implicitly created static LoggerContext not an option for you?

[Yavor16]

We do it because for every step we create new file + new file appender which after they are persisted, are deleted. I tried now to create single LoggerContext instance but the app ran out of memory. I also tried cleaning the new file + removing the appender from the configuration but in the same behavior. Is there anything else I have to close fileAppender.stop(); loggerContext.getConfiguration().getAppenders().remove(fileAppender.getName());

[vy]

@Yavor16, if you need to change the file name, you can just reconfigure the context:

import org.apache.logging.log4j.core.config.Configurator;

URI configSourceUri = new File("/path/to/a/different/log4j2.xml").toURI();
Configurator.reconfigure(configSourceUri);

I tried now to create single LoggerContext instance but the app ran out of memory

Given there is one LoggerContext, I am surprised to see OOM again. What was the culprit in this case?

Is there anything else I have to close

One of the shutdown() methods of LogManager should suffice, you don't need to close every component individually.

@Yavor16, since you're describing a pretty consistent failure scenario, would you mind sharing a minimal reproduction¹ example, please?

¹ A Repro.java containing a main() method triggering the failure. It should only use the Java standard library; no Spring, no Flowable, nothing else. Mind removing every piece of code that doesn't effect the outcome of the failure.

[ppkarwasz]

This is related to #2255: if hundreds of logger contexts are created, but they are not stopped, the application can easily run out of memory.

[Yavor16]

After the advice I tried to create only one LoggerContext and to close every FileAppender after the file has been persisted and the OOM is gone. Unfortunately, know I face a new issue.

java.lang.IllegalStateException: ManagerFactory [org.apache.logging.log4j.core.appender.FileManager$FileManagerFactory@48172888] unable to create manager for [logs/test.log] with data [org.apache.logging.log4j.core.appender.FileManager$FactoryData@3f1853a] at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:148) at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:112) at org.apache.logging.log4j.core.appender.FileManager.getFileManager(FileManager.java:225) at org.apache.logging.log4j.core.appender.FileAppender$Builder.build(FileAppender.java:102)

and also:

ERROR Unable to write to stream logs/test.log for appender ... org.apache.logging.log4j.core.appender.AppenderLoggingException: Error writing to stream logs/test.log

Every step we create new FileAppender that is later closed.

File logFile = new File("test/", fileName); FileAppender fileAppender = FileAppender.newBuilder() .setName(loggerName) .withFileName(logFile.toString()) .setLayout(layoutCreatorFunction.apply(context)) .setConfiguration(context.getConfiguration()) .build()

LoggerConfig loggerConfig = loggerContext.getConfiguration() .getLoggerConfig(loggerName);

loggerConfig.setLevel(Level.DEBUG); loggerConfig.addAppender(fileAppender, Level.DEBUG, null);

loggerContext.updateLoggers(); Logger logger = loggerContext.getLogger(loggerName);

and than we use the 'logger'

do you why does this occur

[rgoers]

We would need to see the logic you use to "close" the file at the end of the step. For your example it is also unclear what will happen if you have multiple instances of the same step running concurrently. If they are all using the same logger name and file name you will most certainly have problems

However, this would be a lot easier if your didn't create a file for every step and instead included a unique step id for the step in every log record. But it is hard to provide a complete recommendation since we don't know what you are doing with the log files after they are closed.

[github-actions[bot]]

This issue is stale because it has been waiting for your feedback for more than 60 days. The Apache Logging Services community values every submitted issue, but without additional information from you, we are unable to provide a solution to your problem. Please comment on this issue or it will be closed in 7 days.