Description
[Note: Probably affects all versions of log4j2, but 2.17, and 2.14.1 I tested]
Quick Description:
When using a appender with FilePattern but without FileName, then log4j2 eats one of the logs (the one generated on boot), then will always lag behind for 1 timeunit (Depending on the kind of rotation)
Ex with Minutes rotation:
[First message ocurring on boot]
- 10:49:18,385 - Now writing to ./logs/13/test.1049.log at 2022-01-13T10:49:18.385+0000
- 10:50:00,007 Log4j2-TF-2-Scheduled-1 DEBUG Rolling ./logs/13/test.1049.log
- 10:50:00,016 Log4j2-TF-2-Scheduled-1 DEBUG GzCompressAction[./logs/13/test.1049.log to ./logs/13/test.1049.log.gz, deleteSource=true]
- 10:50:00,019 Now writing to ./logs/13/test.1049.log at 2022-01-13T10:50:00.019+00
- 10:51:00,001 Log4j2-TF-2-Scheduled-3 DEBUG Rolling ./logs/13/test.1049.log
- 10:51:00,004 Log4j2-TF-2-Scheduled-3 DEBUG RollingFileManager executing async GzCompressAction[./logs/13/test.{*}1049{*}.log to ./logs/13/test.{*}1049{*}.log.gz, deleteSource=true]{}{}{}
We can see that on 4. log4j2 didnt started log 1050.log but recreated 1049.log which will end up deleting the original boot log
Detected on:
https://stackoverflow.com/questions/70695499/log4j2-seems-to-be-lagging-one-time-unit-behind
Ex Configs to replicate issue:
properties:
### Normal log file Configuration appender.fileRotator.type=RollingFile appender.fileRotator.name=fileRotator appender.fileRotator.filePattern=${sys:logs.directory}/$${date:dd}/test.%d{HHmm}.log.gz appender.fileRotator.layout.type=PatternLayout appender.fileRotator.layout.pattern=[%-5level] %d{HH:mm:ss.SSS yyyy-MM-dd} | [%t] %c{1} %L |#| %msg%n appender.fileRotator.policies.type=CronTriggeringPolicy appender.fileRotator.policies.schedule=0 * * ? * * * rootLogger.appenderRef.stdout.ref=fileRotator rootLogger.level=warn status=debug
Xml:
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="warn" name="App" packages=""> <Appenders> <RollingFile name="RollingFile" filePattern="${sys:logs.directory}/$${date:dd}/test.%d{HHmm}.log.gz"> <PatternLayout> <Pattern>%d{ISO8601} | %-5.5p | %-8.8t | %-40.40c{1} | %m%n%ex</Pattern> </PatternLayout> <Policies> <CronTriggeringPolicy schedule="0 0 * * * ?"/> </Policies> </RollingFile> </Appenders> <Loggers> <Root level="info"> <AppenderRef ref="RollingFile"/> </Root> </Loggers> </Configuration>