MartijnVisser opened a new issue, #4362: URL: https://github.com/apache/logging-log4j2/issues/4362
## Description Since 2.25.2, `RollingFileManager.initialFileTime` rounds the file creation time to the nearest second (#3068, #3872). `OnStartupTriggeringPolicy.initialize` compares that value with the JVM start time, and it runs again when another LoggerContext builds an appender for the same file (`AbstractManager.getManager` -> `updateData` -> `setTriggeringPolicy`). So when a second LoggerContext starts, a file that the first context created in the first half of the JVM's start second is rolled, although this JVM created it. In Apache Flink this moves the startup section of affected process logs into `<file>.1` (https://issues.apache.org/jira/browse/FLINK-40833). Expected: a file created by the running JVM is not rolled at startup. ## Configuration **Version:** 2.25.2 and 2.26.1 (2.25.1 is not affected) **Operating system:** Linux **JDK:** 17 ## Logs Status logger output (`-Dlog4j2.debug=true`) of a run that rolled. The JVM started at 14:06:40.175 and the first context created `app.log` at 14:06:40.480, which rounds to 14:06:40.000: ``` 2026-09-28T14:06:40.451215417Z main DEBUG Starting LoggerContext[name=3e3047e6, org.apache.logging.log4j.core.LoggerContext@4d5650ae]... 2026-09-28T14:06:40.481998125Z main DEBUG Starting RollingFileManager /tmp/r/app.log 2026-09-28T14:06:40.485637042Z main DEBUG LoggerContext[name=3e3047e6, org.apache.logging.log4j.core.LoggerContext@4d5650ae] started OK. 2026-09-28T14:06:40.487656292Z main DEBUG Starting LoggerContext[name=895e367, org.apache.logging.log4j.core.LoggerContext@7a3793c7]... 2026-09-28T14:06:40.490702167Z main DEBUG Initiating rollover at startup 2026-09-28T14:06:40.492737542Z main DEBUG RollingFileManager executing synchronous FileRenameAction[/tmp/r/app.log to /tmp/r/app.log.1, renameEmptyFiles=false] 2026-09-28T14:06:40.494809250Z main DEBUG LoggerContext[name=895e367, org.apache.logging.log4j.core.LoggerContext@7a3793c7] started OK. ``` Afterwards `app.log.1` holds `written by the first LoggerContext` and `app.log` holds `written after the second LoggerContext started`. ## Reproduction `Log4jRepro.java`: ```java import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; import java.lang.management.ManagementFactory; import java.net.URL; import java.net.URLClassLoader; import java.nio.file.Files; import java.nio.file.Path; import java.nio.file.Paths; import java.nio.file.attribute.BasicFileAttributes; /** A second LoggerContext re-runs OnStartupTriggeringPolicy on a file this JVM created. */ public class Log4jRepro { public static void main(String[] args) throws Exception { final long jvmStart = ManagementFactory.getRuntimeMXBean().getStartTime(); final Logger log = LogManager.getLogger(Log4jRepro.class); log.info("written by the first LoggerContext"); final Path file = Paths.get(System.getProperty("log.file")); final long created = Files.readAttributes(file, BasicFileAttributes.class).creationTime().toMillis(); // A classloader whose parent is the platform loader gets its own LoggerContext. final ClassLoader isolated = new URLClassLoader(new URL[0], ClassLoader.getPlatformClassLoader()); LogManager.getContext(isolated, false); log.info("written after the second LoggerContext started"); System.out.println( jvmStart + "\t" + created + "\t" + (Math.round(created / 1000d) * 1000 < jvmStart) + "\t" + Files.exists(Paths.get(file + ".1"))); } } ``` `log4j2.properties`: ``` appender.file.type = RollingFile appender.file.name = File appender.file.fileName = ${sys:log.file} appender.file.filePattern = ${sys:log.file}.%i appender.file.layout.type = PatternLayout appender.file.layout.pattern = %m%n appender.file.policies.type = Policies appender.file.policies.startup.type = OnStartupTriggeringPolicy appender.file.strategy.type = DefaultRolloverStrategy rootLogger.level = INFO rootLogger.appenderRef.file.ref = File ``` It prints the JVM start, the file creation time, whether the rounded creation time is before the JVM start, and whether the file was rolled. It rolls in about a third of the runs, exactly the ones where the third column is `true`: ``` CP=.:log4j-api-2.26.1.jar:log4j-core-2.26.1.jar javac -cp $CP Log4jRepro.java for i in $(seq 1 100); do rm -f app.log* java -Dlog.file=app.log -Dlog4j.configurationFile=log4j2.properties -cp $CP Log4jRepro done | awk '$4 == "true"' | wc -l ``` 100 runs each: 2.25.1 rolled 0 times, 2.25.2 34 times, 2.26.1 33 times. -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
