memory leak possible in log4j-core

[testpradnya]

Description

[A clear and concise description of what the bug is.]
Memory leak possible in log4j-core. We are getting memory leak (OOM)- java core in
We are running our process which uses Log4j 2.20 on Windows and Linux crashes with OutOfMemory error after about a week or in 2-3 days. The other process which uses log4j running on Windows and Linux has been running for months with no issues.

Error: Dump Event "systhrow" (00040000) Detail "java/lang/OutOfMemoryError" "Java heap space" received

Configuration

Version: [Log4j version] 2.20.0

Operating system: [OS and version] Windows 2019, Linux RHEL 8.8

JDK: [JDK distribution and version] JDK 8.0.8.10 and JDK 8.0.8.15

Logs

[Stacktraces, errors, etc. relevant applications logs.]
[javacore.20240124.144506.590065.0006.txt](https://github.com/apache/logging-log4j2/files/14083857/javacore.20240124.144506.590065.0006.txt)

Reproduction

[An isolated test reproducing the test.
JUnit tests similar to the ones in the code base are extremely appreciated.]

[ppkarwasz]

@testpradnya,

Can you provide your Log4j Core configuration? There is roughly one AbstractManager per appender. In order to have 24k managers, you must be using RoutingAppender or register them programmatically.

[testpradnya]

Thank you @ppkarwasz for the reply.

Upon getting HTTP request-> we are creating logger using following program->
So we have too many loggers

private void finishAdd(Appender appender, LogConfigItem lci) {
		final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
		final Configuration config = ctx.getConfiguration();

		appender.start();
		config.addAppender(appender);

		AppenderRef[] refs = new AppenderRef[] { AppenderRef.createAppenderRef(appender.getName(), null, null) };
		j++;
		loggerName=loggerName+Integer.toString(j);		
		String strLog = lci.getLogLevel();
		if(strLog == null) //added validation: if the log level is not set by the user, set it to Level.INFO.
			strLog = "Level.INFO";
		Level level = Level.getLevel(strLog);
		LoggerConfig loggerConfig = LoggerConfig.createLogger(false, level, loggerName,
				"false", refs, null, config, null );
		loggerConfig.addAppender(appender, null, null);
		config.addLogger(loggerName, loggerConfig);
		ctx.updateLoggers();

		myLogger = LogManager.getLogger(loggerName);
}

Let me know if you need more information.
Thanks

[ppkarwasz]

So we have too many loggers

No, you have too many appenders:

• loggers are the entry point of the logging system. They are relatively lightweight objects and a typical system has thousands of them;
• appenders are the exit point of the logging system. They are heavy objects, since they usually open resources (file descriptors, database connections, etc.).

Look at architecture for details.

The problem with your code is that you are starting thousands of appenders through Appender#start(), but you don't close them through Appender#stop().

As far as I understand, you want to separate your logs per HTTP request. There are better alternatives to creating a new appender at each request.

Alternative 1: structured logging

You can use ThreadContext to add a unique identifier to each HTTP Request and use a structured layout such as JTL to make log events easily parseable by your log management system.

Alternative 2: routing appender

A routing appender (cf. documentation) allows you to create appenders on the fly, as in your approach.

The main difference is that it supports a PurgePolicy that can close appenders when they are no longer needed.

A sample configuration:

<Routing name="Routing">
  <Routes pattern="$${ctx:requestId}}">
    <Route>
      <File name="File-${ctx:requestId}" fileName="/var/log/${ctx:requestId}.log"/>
    </Route>
  </Routes>
  <IdlePurgePolicy timeToLive="2" timeUnit="minutes"/>
</Routing>

[testpradnya]

Thank you @ppkarwasz for the reply.
I get your point that I am starting different appender objects but not stopping those.
We are creating different appenders like console, file, rolling file, daily rolling file and so on.

Can you tell me or help me in understand how can I stop those appenders?
Follows my method for adding appender for DailyRollingFile. I have similar methods for various appenders.

public void addDailyRollingFile(LogConfigItem lci, Map<String, Object> map) throws Exception {

		String fileName = lci.getStringParameter("DailyRollingFile.File");
		String datePattern = lci.getStringParameter("DailyRollingFile.DatePattern");
		String filePattern = fileName + "%d{" + datePattern + "}";

		String encoding = lci.getStringParameter("DailyRollingFile.Encoding");
		
		appenderName = "DailyRollingFile." + getId();
		loggerName = appenderName;

		RollingFileAppender fileAppender = RollingFileAppender.newBuilder()
				.setName(appenderName)
				.setLayout(getLayout(lci, encoding))
				.withFileName(fileName)
				.withFilePattern(filePattern)
				.withPolicy(TimeBasedTriggeringPolicy.newBuilder().build())
				.withStrategy(DefaultRolloverStrategy.newBuilder().build())
				.build();
		
		finishAdd(fileAppender, lci);
	}

In every method appender and filename etc are local variables. I pasted you finishAdd method earlier.
I have Logger variable which is object's attribute. How can I stop appenders when I have only Logger object. How to reach appender level from Logger object?

Any pointer/guidance is appreciated.

Thanks

[pradnyagandhe]

Hi @ppkarwasz
After the changes made in the code - I am closing and removing the appender.
Still we get the memory leak and we are encountering core dump.
The class "org.apache.logging.log4j.core.appender.AbstractManager" occupies 1.14 GB (58.42%) bytes. The memory is accumulated in one instance of "java.util.HashMap$Node[]" which occupies 1.14 GB (58.42%) bytes.

This hashmap, named MAP, contains many key-value pairs, I have expanded a couple of them here:

Based on the attached MAT analysis of core dump image, I have following query->
If this large amount of memory usage by log4j is necessary, should we consider increasing heap size?

Please let me know.

[ppkarwasz]

@pradnyagandhe,

These seem to be entries for 131072 instances of DefaultConfiguration.

If you use a component builder and do not call the setConfiguration method, some rare components create an new configuration for you, instead of logging an ERROR and returning null as we do for most missing required parameters.

Can you show us your getLayout method (the only call sites of new DefaultConfiguration() I find are for old layouts)?

[pradnyagandhe]

Hi @ppkarwasz
Appreciate your response!!
Follows the getLayout method.

private Layout<? extends Serializable> getLayout(LogConfigItem lci, String encoding) {
		Charset charSet = null;
		if (encoding != null && !encoding.isEmpty() && Charset.isSupported(encoding))
			charSet = Charset.forName(encoding);

		String layout = lci.getStringParameter(LogUtils.LAYOUT);
		if (layout == null)
			return null;
		switch (layout) {
		case "Simple":
			return PatternLayout.newBuilder().withPattern(SIMPLE_LAYOUT).withCharset(charSet).build();
		case "HTML":
			return HtmlLayout.newBuilder().withCharset(charSet).build();
		case "XML":
			return XmlLayout.newBuilder().build();
		default:
		return PatternLayout.newBuilder().withCharset(charSet).
				withPattern(lci.getStringParameter(CONVERSION_PATTERN)).build();

		}
	}

[ppkarwasz]

TL;DR Always call withConfiguration on our component builders.

As a principle you should always supply a Configuration parameter to these components:

return PatternLayout.newBuilder()
        .withConfiguration(configuration)
        .withPattern(SIMPLE_LAYOUT)
        .withCharset(charSet)
        .build();

Failing to do so on Log4j Core 2.20.0 will limit the number of available patterns. See my comment in #756:

Looking at the available PatternConverters, the color converters, "enc", "equals*", "highlight", "maxLength", "replace", "style", "ex*" require a configuration to create a PatternParser.

Failing to do so on Log4j Core 2.17.1 or earlier will cause a lot of DefaultConfigurations to be created and never released (I suspect you use this version on your production servers).

[pradnyagandhe]

Hi @ppkarwasz
Sorry for the delayed reply.
We are using log4j 2.20.0 version.
I see that we are using withPattern and withCharset with newBuilder method for Simple, HTML and default layout. We are not passing anything with newBuilder method for XML layout.
We use mostly default layout for log file.
What would you recommend to use for the layout? Can you please re-iterate or explain?

Thanks

[ppkarwasz]

Every time you call newBuilder() (it doesn't matter on which component), you should call withConfiguration, e.g.:

final org.apache.logging.log4j.spi.LoggerContext lc = LogManager.getContext(false);
if (lc instanceof LoggerContext) {
    LoggerContext context = (LoggerContext) lc;
    RollingFileAppender fileAppender = RollingFileAppender.newBuilder()
            .withConfiguration(context.getConfiguration())
            .setName(appenderName)
            ...

Failing to do so might result in a new DefaultConfiguration being initialized (and never stopped).

[pradnyagandhe]

Ok @ppkarwasz
I will use, check and get back to you. Thank you the reply.

[pradnyagandhe]

Hi @ppkarwasz ,
I did the following code changes

                   `ctx = (LoggerContext) LogManager.getContext(false);			
		FileAppender fileAppender = FileAppender.newBuilder()
				.withConfiguration(ctx.getConfiguration())
				.setName(appenderName)
				.setLayout(PatternLayout.newBuilder().withPattern(pattern).withCharset(charSet).build())
				.withFileName(appender.getFile())
				.build();`

But I don't see the change in performance of our server process. The server process receives OOM

It looks like the same object accumulates in the HashMap

Can these be removed from the map when the AL thread is finished using it? Every httprequest thread is generating a new log output stream for each instance.

Can you guide me further?
Sharing the source file in which we have implemented log4j2 library.

Thanks

[pradnyagandhe]

72_tdilog4j.txt
Hi @ppkarwasz
Yes, I have called withConfiguration on PatternLayout and all other components.
Let me share my source file with you.
Pls advise further.
Thanks

[pradnyagandhe]

Any update sir @ppkarwasz ?
Do you get a chance to go through the attached source file?
Let me know.
Thanks

[ppkarwasz]

@pradnyagandhe,

Truth be told, the notification about your April 5th must have been lost among all the Github notification we have been receiving recently. I'll try to look at it, when I find some time.

Since this problem has been affecting you since January, consider reaching me directly through the e-mail address or LinkedIn account on my Github profile.

[pradnyagandhe]

Hi @ppkarwasz
As suggested by you in the earlier update-> I tried using Routing log4j2 configuration.
I used following->

<Routing name="Routing">
	<Routes pattern="$${ctx:requestId}}">
		<Route>
			<RollingFile name="childallog" append="true" fileName="logs/childallog.log" filePattern="logs/childallog-%i.%d{yyyy-MM-dd}.log">
				<PatternLayout pattern="%d{DEFAULT} %-5p [%c] - %m%n"/>
				<Policies>
					<OnStartupTriggeringPolicy minSize="1" />
					<SizeBasedTriggeringPolicy size="100MB" />
				</Policies>
				<DefaultRolloverStrategy max="3" fileIndex="min" />
			</RollingFile>
		</Route>
	</Routes>
	<IdlePurgePolicy timeToLive="1" timeUnit="minutes"/>
</Routing>

With this log configuration, we are observing OOM issue.
I have following query ->

1. How to use $ variable in log4j2 configuration file?

Attaching whole log4j2.txt (xml) for your reference.
log4j2.txt

Highly appreciate your reply.

Thanks

[ppkarwasz]

For each requestId the routing appender creates a new appender, so the name, fileName and filePattern attributes must be unique:

<RollingFile name="childallog-${ctx:requestId}"
                      append="true"
                      fileName="logs/${ctx:requestId}/childallog.log"
                      filePattern="logs/${ctx:requestId}/childallog-%i.%d{yyyy-MM-dd}.log">
    <PatternLayout pattern="%d{DEFAULT} %-5p [%c] - %m%n"/>
    <Policies>
        <OnStartupTriggeringPolicy minSize="1" />
        <SizeBasedTriggeringPolicy size="100MB" />
    </Policies>
    <DefaultRolloverStrategy max="3" fileIndex="min" />
</RollingFile>

Remark the usage of ${ctx:requestId} instead of $${ctx:requestId}: the XML inside <Route> is not evaluated at configuration time, but whenever there is the need for a new appender, so it is "lazy by default".