[jira] [Created] (LOG4J2-3155) OnStartupTriggeringPolicy doesn't take file create time precision into account

["David Morávek (Jira)" <ji...@apache.org>]

David Morávek created LOG4J2-3155:
-------------------------------------

             Summary: OnStartupTriggeringPolicy doesn't take file create time precision into account
                 Key: LOG4J2-3155
                 URL: https://issues.apache.org/jira/browse/LOG4J2-3155
             Project: Log4j 2
          Issue Type: Bug
          Components: Appenders
    Affects Versions: 2.14.1
            Reporter: David Morávek


Context:
 * There is a log4j context per ClassLoader (see *ClassLoaderContextSelector* for more details)
 * Each context holds related loggers and these loggers need an *appender*. There is a single appender instance per context. This means we'll actually have two *RollingFileAppenders* (because we have two classloaders).
 * This should be OK, because these two appenders use a single shared instance of *RollingFileManager*.

Problem is following:
 * We're using *OnStartupTriggeringPolicy* [1].
 * When the second RollingFileAppender is constructed (when initializing second context), we re-configure [2] *RollingFileManager* .
 * This results in re-initialization of all policies, which stresses this condition [3] again. This time file is already non-empty, so the second part may pass.
 * 
The actual problem is the first part of the check, which basically checks if _log_file_create_time_ms < jvm_startup_time_ms_. File create time precision is *filesystem dependent*. Ext4 and AppleFS are using *SECOND* precision. If log file is created in the same second as JVM is started, file gets rotated on re-initialization.

Here is log4j config we are using [4].

This was discovered while debugging a flakiness of a test that watches for messages logged in a sub-process.

Whilst this is could be easily fixed on test side by re-configuring log4j, I think this would deserve a proper fix.

I think the simplest approach would be just switching to second precision in *OnStartupTriggeringPolicy* [1]. Basically condition would look as follows:

_log_file_create_time_s < jvm_startup_time_s_

Alternatively precision can be chosen based on underlying file-system.


[1] [https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java|https://github.com/apache/logging-log4j2/blob/rel/2.14.1/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java]
[2] [https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AbstractManager.java#L120|https://github.com/apache/logging-log4j2/blob/rel/2.14.1/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/AbstractManager.java#L120]
[3] [https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java#L77|https://github.com/apache/logging-log4j2/blob/rel/2.14.1/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/OnStartupTriggeringPolicy.java#L78]

[4] [https://github.com/apache/flink/blob/release-1.13.2/flink-dist/src/main/flink-bin/conf/log4j.properties]

 



--
This message was sent by Atlassian Jira
(v8.3.4#803005)