Unusual immediateFlush behaviour

[daniel-b2c2]

Disclaimer: I am not an expert in log4j, I am giving the fullest and best account possible of what I've tried.

For the last 9 months I've been trying to keep up with the log4j version upgrades as and when they come out.

I tried to upgrade from version <2.23.x to 2.23.x, when I ran my application in a test environment, I found the logs were full of NoClassFound warnings, the situation described here: #2835

Hindsight is 20/20 but this turned out to be a bug that was fixed in a later version however, this was not known at the time.

At the time I concluded that the packages="org.apache.logging.log4j.core,io.sentry.log4j2" attribute in my log4j2.xml was

• deprecated
• causing the above classpath scanning (bug) to be triggered - at least removing it seemed to make it happy.

So assuming this was the new expected behaviour, I removed this attribute.

This was a mistake.

There are 2 plugins in my app:

• at least sentry,
• and possibly log4j.core itself

This is probably why that package attribute has the values it has, as a result there are two Log4J2plugins.dat files on the classpath and in the absence of a special maven plugin to concatenate these two, this causes trouble.

We don't use maven (using bazel), so we're out of luck with the plugin concat.

The result meant that there was no log output, this is because the log4j.core file wasn't being picked up, and the log4j logs show this was indeed a problem:

2024-12-20T03:12:05.571082003Z main ERROR Unrecognized format specifier [d]
2024-12-20T03:12:05.571171044Z main ERROR Unrecognized conversion specifier [d] starting at position 16 in conversion pattern.
2024-12-20T03:12:05.571319204Z main ERROR Unrecognized format specifier [thread]
2024-12-20T03:12:05.571408660Z main ERROR Unrecognized conversion specifier [thread] starting at position 25 in conversion pattern.
2024-12-20T03:12:05.571558704Z main ERROR Unrecognized format specifier [level]
2024-12-20T03:12:05.571668318Z main ERROR Unrecognized conversion specifier [level] starting at position 35 in conversion pattern.
2024-12-20T03:12:05.571776562Z main ERROR Unrecognized format specifier [logger]
2024-12-20T03:12:05.571855948Z main ERROR Unrecognized conversion specifier [logger] starting at position 47 in conversion pattern.
2024-12-20T03:12:05.571954175Z main ERROR Unrecognized format specifier [msg]
2024-12-20T03:12:05.572039126Z main ERROR Unrecognized conversion specifier [msg] starting at position 54 in conversion pattern.
2024-12-20T03:12:05.572141580Z main ERROR Unrecognized format specifier [n]
2024-12-20T03:12:05.572248398Z main ERROR Unrecognized conversion specifier [n] starting at position 56 in conversion pattern.

So I go back to the previously working version that picks up the core slf4j, but not the sentry plugin and I sit tight hoping for a fix in the form of log4j3.

Fast forward to beta testing log4j3: So I understand that as part of log4j 3, you don't have to run a concatenating processor over the .dat files, and so the plugins should just work out of the box. I tried log4j 3, and found that there were no errors relating to log4j itself - so far so good, but there were still no log entries in the log files - until I killed my app at which point 45 minutes worth of logs were dumped to a file. This was a repeatable process - i.e. restart the app, get a dump of logs (complete I might add).

I found my RollingRandomAccessFile has a immediateFlush attribute which is set to false. This has never meant 'store 45 minutes of logs' it's always meant 'don't flush immediately' so a few lines maybe even a few hundred lines relating to the last few seconds, but not 45 minutes of logs.

If I set this flush attribute to true, then I get the 'normal' logging behaviour, but this will kill our performance.

So as of right now, I think I can only be on log4j3 to enable plugins properly, so I can be without the package attribute in the file, but the immediateFlush seems to not be what it used to be. The behaviour I've seen would be best described as dontFlushTillShutdown

Sorry for the long background, but it's important to see how I got in this situation. So my question:

Did something change with immediateFlush to make it take a long time to flush?

There are a lot of moving parts to log4j and this issue, and I have tried to nail things down the best I can so it would be nice if somebody could confirm the following:

• It's not necessary to run any concatenating processor in log4j3, the log4j2plugin.dat files will get picked up even if there are multiple plugins?
• I should be able to do away with the package attribute in log4j3?

[ppkarwasz]

until I killed my app at which point 45 minutes worth of logs were dumped to a file. This was a repeatable process - i.e. restart the app, get a dump of logs (complete I might add).

What does 45 minutes worth of logs mean in term of size? The RollingRandomAccessFile and RandomAccessFile appenders have a larger buffer (256 KiB instead of 8 KiB) to format log events. Log events should be written to the OS once this buffer becomes full.

• It's not necessary to run any concatenating processor in log4j3, the log4j2plugin.dat files will get picked up even if there are multiple plugins.

When you shade two Log4j Core 3 JARs, you still need to merge META-INF/services/* files, but shading tools usually know how to do it.
#2887

Personally I find shading a bad practice from a security point of view (it makes SCA analysis harder). There are other ways to create single-JAR applications that do not involve shading, see How do I create a single-JAR application containing Log4j Core.

If shading is really important for you, we could consider merging #2887, so that you can merge two Log4j2Plugins.dat files by concatenating them.

• I should be able to do away with the package attribute in Log4j 3

The attribute should be ignored in Log4j Core 3.

[daniel-b2c2]

The attribute should be ignored in Log4j Core 3.

Thanks I will remove it from the config when using log4j 3.

Thanks for the above info, just for more context we're not using a shading plugin. Though one of the libraries we're using might itself use a shaded version of log4j, but we aren't shading as part of our build.

I will try to find out exactly how much data is being written and if it writes outside of being restarted. Is it sufficient to just measure the size of the log text in terms of kb? See below

[daniel-b2c2]

So I've confirmed it is flushing periodically not just on restart.
Worth noting this isn't a particularly heavy logging process, actually it's only writing the same log message every 1 second.

I ran the following analysis on it, given the following mockup log text:

LAST PARTIALLY WRITTEN LOG STATEMENT GOES H

I ran the following to extract the size of the text that was written by a subsequent flush:

awk '/LAST PARTIALLY WRITTEN LOG STATEMENT GOES H/ {found=1; next} found' /var/log/logfile.log  | wc -c
262088

which ... 262088bytes in kib =~= 256 kibibytes... according to google.

So that aligns with the buffer explanation you gave, i.e. system is behaving as expected, the buffer is filling up, and then getting flushed to disk. Though I'm curious if there are other triggers that would have flushed it sooner? As the gap here was 30 minutes of log data.

Looking at the docs:

https://logging.apache.org/log4j/2.x/manual/appenders.html

The buffer is flushed to the underlying resource on three occasions:

• if the buffer is full.

• at the end of each log event batch, if asynchronous loggers or appenders are used.
  ...

• Per the docs above, there's apparently the concept of a log event 'batch' I'm unclear what that is?
• I'm also unclear from the config below, if the above documentation is applicable, as we're not using <Async> explicitly but we're setting -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector so, I'm fairly sure it's async as a result and the docs are relevant, do confirm?

<Appenders>
...
         <RollingRandomAccessFile name="File"
                                 fileName="${log_path}/${svc_name}.log"
                                 filePattern="${log_path}/$${date:yyyy-MM}/${svc_name}-%d{yyyy-MM-dd}.log.gz"
                                 immediateFlush="false">
            <PatternLayout>
                <Pattern>%d %-5p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <DefaultRolloverStrategy max="7"/>
        </RollingRandomAccessFile>

...
<Loggers>
     <Root level="${log_root_level}" includeLocation="false">
            <AppenderRef ref="File" level="${log_file_level}"/>

I'm going to check what the behaviour was in a previous version (and what libraries I was using), I know the log4j.xml has not changed, it's only versions that I've changed. I'm sure it was logging every line straight away, or certainly more than 30 minutes.

[ppkarwasz]

Looking at the docs:

https://logging.apache.org/log4j/2.x/manual/appenders.html
The buffer is flushed to the underlying resource on three occasions:

• if the buffer is full.
• at the end of each log event batch, if asynchronous loggers or appenders are used.
  ...

• Per the docs above, there's apparently the concept of a log event 'batch' I'm unclear what that is?

The concept of batch appears only if you use asynchronous loggers or appenders, which rely on a queue/buffer ring of log events. Your application threads will fill the queue with events and an asynchronous thread will deliver them to the destination. The end of batch corresponds to the situation, when the asynchronous thread manages to empty the queue.

• I'm also unclear from the config below, if the above documentation is applicable, as we're not using <Async> explicitly but we're setting -Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector so, I'm fairly sure it's async as a result and the docs are relevant, do confirm?

You are using Log4j Core 3, right? Then you should follow the Log4j Core 3 documentation. To use asynchronous logger you need to:

• Add org.apache.logging.log4j:log4j-async-logger to your runtime dependencies.
• Set the log4j.loggerContext.selector configuration property to org.apache.logging.log4j.async.logger.AsyncLoggerContextSelector (e.g. as Java System Property or in a log4j2.component.properties file). Note that both the name and value of the property changed.
• Remove the old log4j2.contextSelector configuration property (which is still supported through a backward-compatibility mechanism).

[daniel-b2c2]

It's working!

So here's roughly what was missing.

• I hadn't noticed both the key and value had changed for AsyncLoggerContextSelector I had assumed it was the same.
• On changing it, the journalctl output (where log4j configuration logs are sent), showed that the log4j-async-logger was not available - this was my fault, even though I had added it to the bazel dependency set, I had forgotten to export the packages for use, so it wasn't actually on the classpath.

Absolutely delighted as with version 3 as it doesn't require fiddling with the log4jplugin.dat files.

One final question:

For performance reasons in log4j2 we used:

-Dlog4j2.clock=org.apache.logging.log4j.core.util.CachedClock

Has there been a change of key, and the class used? I can see it's moved to org.apache.logging.log4j.core.time.internal so I assume I'm not to reference it directly given it's internal? (I looked in https://logging.apache.org/log4j/3.x/migrate-from-log4j2.html but didn't see any remarks).

Reading the source code it appears to be log4j.Clock=CachedClock, please confirm?

Thank you so much for the assistance.

[ppkarwasz]

For performance reasons in log4j2 we used:

Did you actually measure the performance gain/loss of your configuration choices? Performance strongly depends on the workflow of your application and there is no "one size fits it all" solution. If your application logs less than 1 MiB/hour I would try synchronous logging and the default clock setting first.

-Dlog4j2.clock=org.apache.logging.log4j.core.util.CachedClock

All the "official" property names for properties changed, but as I mentioned above there is a backward-compatibility mechanism to map old property names to the new ones.
The official property name for the clock is log4j.configuration.clock (see documentation), which accepts, besides a fully qualified implementation name, also 4 predefined constants.
You can use:

-Dlog4j.configuration.clock=CachedClock

Remark: you should really run a benchmark to see if CachedClock is the right choice for you. Access to the current time is already strongly optimized on most systems. E.g. in Linux the current timestamp is shared via vdso, so clock_gettime is extremely fast, no need to optimize it.

If you are only printing milliseconds, you SystemClockMillis could be a better choice.

[daniel-b2c2]

Thanks for the documentation link and advice. 🙏

For completeness, the test application I used in the example above doesn't need the cachedclock as it's not performance sensitive. But there are others that do, and these are latency sensitive (rather than throughput). Somebody smarter than me has run the performance tests and concluded we may benefit from this, though this analysis may be outdated, so we'll check again.

Once again thanks, very excited to see log4j 3.0GA soon 🚀