[
https://issues.apache.org/jira/browse/LOG4J2-3339?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Miguel Valente updated LOG4J2-3339:
-----------------------------------
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]
# {{{color:#57d9a3}10:49:18,385{color} - Now writing to
./logs/13/test.1049.log at 2022-01-13T10:49:18.385+0000}}
# {{{color:#ffab00}10:50:00,007{color} Log4j2-TF-2-Scheduled-1 DEBUG Rolling
./logs/13/test.1049.log}}
# {{{color:#ffab00}10:50:00,016{color} Log4j2-TF-2-Scheduled-1 DEBUG
GzCompressAction[./logs/13/test.1049.log to ./logs/13/test.1049.log.gz,
deleteSource=true]}}
# {{{color:#ffab00}10:50:00,019{color} Now writing to
./logs/13/test.{color:#de350b}*1049*{color}.log at
2022-01-13T{*}10:50:00.019+00{*}}}
# {{{color:#4c9aff}10:51:00,001{color} Log4j2-TF-2-Scheduled-3 DEBUG Rolling
./logs/13/test.1049.log}}
# {{{}{color:#4c9aff}10:51:00,004{color} 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
Using one of the following configs:
Relates with report on:
[https://stackoverflow.com/questions/70695499/log4j2-seems-to-be-lagging-one-time-unit-behind]
Ex Configs to replicate:
properties:
{code:java}
### 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 {code}
Xml:
{code:java}
<?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> {code}
was:
[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]
# {{{color:#57d9a3}10:49:18,385{color} - Now writing to
./logs/13/test.1049.log at 2022-01-13T10:49:18.385+0000}}
# {{{color:#ffab00}10:50:00,007{color} Log4j2-TF-2-Scheduled-1 DEBUG Rolling
./logs/13/test.1049.log}}
# {{{color:#ffab00}10:50:00,016{color} Log4j2-TF-2-Scheduled-1 DEBUG
GzCompressAction[./logs/13/test.1049.log to ./logs/13/test.1049.log.gz,
deleteSource=true]}}
# {{{color:#ffab00}10:50:00,019{color} Now writing to
./logs/13/test.{color:#de350b}*1049*{color}.log at
2022-01-13T{*}10:50:00.019+00{*}}}
# {{{color:#4c9aff}10:51:00,001{color} Log4j2-TF-2-Scheduled-3 DEBUG Rolling
./logs/13/test.1049.log}}
# {{{}{color:#4c9aff}10:51:00,004{color} 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
Using one of the following configs:
Relates with report on:
[https://stackoverflow.com/questions/70695499/log4j2-seems-to-be-lagging-one-time-unit-behind]
Ex Configs to replicate:
properties:
* {{ ### Normal log file Configuration
appender.fileRotator.type=RollingFile}}{{appender.fileRotator.name=fileRotator}}{color:#ffab00}*{{appender.fileRotator.filePattern=${sys:logs.directory}/$${date:dd}/test.%d\{HHmm}.log.gz}}*{color}{{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>
> FilePattern doesn't rotate correctly when not using a Filename
> --------------------------------------------------------------
>
> Key: LOG4J2-3339
> URL: https://issues.apache.org/jira/browse/LOG4J2-3339
> Project: Log4j 2
> Issue Type: Bug
> Components: Appenders
> Affects Versions: 2.14.1, 2.17.0
> Reporter: Miguel Valente
> Priority: Minor
>
> [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]
> # {{{color:#57d9a3}10:49:18,385{color} - Now writing to
> ./logs/13/test.1049.log at 2022-01-13T10:49:18.385+0000}}
> # {{{color:#ffab00}10:50:00,007{color} Log4j2-TF-2-Scheduled-1 DEBUG Rolling
> ./logs/13/test.1049.log}}
> # {{{color:#ffab00}10:50:00,016{color} Log4j2-TF-2-Scheduled-1 DEBUG
> GzCompressAction[./logs/13/test.1049.log to ./logs/13/test.1049.log.gz,
> deleteSource=true]}}
> # {{{color:#ffab00}10:50:00,019{color} Now writing to
> ./logs/13/test.{color:#de350b}*1049*{color}.log at
> 2022-01-13T{*}10:50:00.019+00{*}}}
> # {{{color:#4c9aff}10:51:00,001{color} Log4j2-TF-2-Scheduled-3 DEBUG Rolling
> ./logs/13/test.1049.log}}
> # {{{}{color:#4c9aff}10:51:00,004{color} 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
>
> Using one of the following configs:
> Relates with report on:
> [https://stackoverflow.com/questions/70695499/log4j2-seems-to-be-lagging-one-time-unit-behind]
>
> Ex Configs to replicate:
> properties:
> {code:java}
> ### 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 {code}
> Xml:
> {code:java}
> <?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> {code}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
