[
https://issues.apache.org/jira/browse/LOG4J2-2284?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Hartmut Honisch updated LOG4J2-2284:
------------------------------------
Description:
I have a log4j config that uses RollingFileAppender with
TimeBasedTriggeringPolicy to create one logfile per minute (well in reality
it’s actually one logfile per day, but testing/reproducing the described
behaviour is easier when you don’t have to wait an entire day for the logfile
rolling to occur, and the bug described here applies to both rolling per day
and rolling per minute).
I would expect that each logfile contains only log entries written within the
same minute that’s suggested by its filename, for example:
* Logfile app.2018-03-21_*10-00*.log contains log messages starting with
timestamp 2018-03-21 *10:00*
* Logfile app.2018-03-21_*10-01*.log contains log messages starting with
timestamp 2018-03-21 *10:01*
* Logfile app.2018-03-21_*10-02*.log contains log messages starting with
timestamp 2018-03-21 *10:02*
* …
However that’s not the case: When I start the application, the first logfile
created contains log messages from both the minute suggested by its filename
and the next minute, and all subsequent logfiles contain messages that are off
by 1 minute compared to the logfile name. For example, let’s say I start the
app on 2018-03-21 10:00:01 Then the logfiles contain the following messages:
* Logfile app.2018-03-21_*10-00*.log contains log messages starting with
timestamp 2018-03-21 *10:00* and 2018-03-21 *10:01*
* Logfile app.2018-03-21_*10-01*.log contains log messages starting with
timestamp 2018-03-21 *10:02*
* Logfile app.2018-03-21_*10-02*.log contains log messages starting with
timestamp 2018-03-21 *10:03*
* …
I’m using the following log4j configuration
{{<?xml version="1.0" encoding="UTF-8"?>}}
{{<Configuration status="warn">}}
{{ <Appenders>}}
{{ <RollingFile name="app_log"
filePattern="logs/app.%d\{yyyy-MM-dd_HH-mm}.log">}}
{{ <PatternLayout>}}
{{ <Pattern>%d\{DEFAULT} - %m%n</Pattern>}}
{{ </PatternLayout>}}
{{ <Policies>}}
{{ <TimeBasedTriggeringPolicy modulate="true"/>}}
{{ </Policies>}}
{{ </RollingFile>}}
{{ </Appenders>}}
{{ <Loggers>}}
{{ <Root level="info">}}
{{ <AppenderRef ref="app_log" level="info"/>}}
{{ </Root>}}
{{ </Loggers>}}
{{</Configuration>}}
was:
I have a log4j config that uses RollingFileAppender with
TimeBasedTriggeringPolicy to create one logfile per minute (well in reality
it’s actually one logfile per day, but testing/reproducing the described
behaviour is easier when you don’t have to wait an entire day for the logfile
rolling to occur, and the bug described here applies to both rolling per day
and rolling per minute.
I would expect that each logfile contains only log entries written within the
same minute that’s suggested by its filename, for example:
* Logfile app.2018-03-21_*10-00*.log contains log messages starting with
timestamp 2018-03-21 *10:00*
* Logfile app.2018-03-21_*10-01*.log contains log messages starting with
timestamp 2018-03-21 *10:01*
* Logfile app.2018-03-21_*10-02*.log contains log messages starting with
timestamp 2018-03-21 *10:02*
* …
However that’s not the case: When I start the application, the first logfile
created contains log messages from both the minute suggested by its filename
and the next minute, and all subsequent logfiles contain messages that are off
by 1 minute compared to the logfilen ame. For example, let’s say I start the
app on 2018-03-21 10:00:01 Then the logfiles contain the following messages:
* Logfile app.2018-03-21_*10-00*.log contains log messages starting with
timestamp 2018-03-21 *10:00* and 2018-03-21 *10:01*
* Logfile app.2018-03-21_*10-01*.log contains log messages starting with
timestamp 2018-03-21 *10:02*
* Logfile app.2018-03-21_*10-02*.log contains log messages starting with
timestamp 2018-03-21 *10:03*
* …
I’m using the following log4j configuration
{{<?xml version="1.0" encoding="UTF-8"?>}}
{{<Configuration status="warn">}}
{{ <Appenders>}}
{{ <RollingFile name="app_log"
filePattern="logs/app.%d\{yyyy-MM-dd_HH-mm}.log">}}
{{ <PatternLayout>}}
{{ <Pattern>%d\{DEFAULT} - %m%n</Pattern>}}
{{ </PatternLayout>}}
{{ <Policies>}}
{{ <TimeBasedTriggeringPolicy modulate="true"/>}}
{{ </Policies>}}
{{ </RollingFile>}}
{{ </Appenders>}}
{{ <Loggers>}}
{{ <Root level="info">}}
{{ <AppenderRef ref="app_log" level="info"/>}}
{{ </Root>}}
{{ </Loggers>}}
{{</Configuration>}}
> Logfile rolling broken with RollingFileAppender and TimeBasedTriggeringPolicy
> -----------------------------------------------------------------------------
>
> Key: LOG4J2-2284
> URL: https://issues.apache.org/jira/browse/LOG4J2-2284
> Project: Log4j 2
> Issue Type: Bug
> Components: Core
> Affects Versions: 2.10.0, 2.11.0
> Environment: Windows 10, Java 1.8.161
> Reporter: Hartmut Honisch
> Priority: Major
>
> I have a log4j config that uses RollingFileAppender with
> TimeBasedTriggeringPolicy to create one logfile per minute (well in reality
> it’s actually one logfile per day, but testing/reproducing the described
> behaviour is easier when you don’t have to wait an entire day for the logfile
> rolling to occur, and the bug described here applies to both rolling per day
> and rolling per minute).
> I would expect that each logfile contains only log entries written within the
> same minute that’s suggested by its filename, for example:
> * Logfile app.2018-03-21_*10-00*.log contains log messages starting with
> timestamp 2018-03-21 *10:00*
> * Logfile app.2018-03-21_*10-01*.log contains log messages starting with
> timestamp 2018-03-21 *10:01*
> * Logfile app.2018-03-21_*10-02*.log contains log messages starting with
> timestamp 2018-03-21 *10:02*
> * …
>
> However that’s not the case: When I start the application, the first logfile
> created contains log messages from both the minute suggested by its filename
> and the next minute, and all subsequent logfiles contain messages that are
> off by 1 minute compared to the logfile name. For example, let’s say I start
> the app on 2018-03-21 10:00:01 Then the logfiles contain the following
> messages:
> * Logfile app.2018-03-21_*10-00*.log contains log messages starting with
> timestamp 2018-03-21 *10:00* and 2018-03-21 *10:01*
> * Logfile app.2018-03-21_*10-01*.log contains log messages starting with
> timestamp 2018-03-21 *10:02*
> * Logfile app.2018-03-21_*10-02*.log contains log messages starting with
> timestamp 2018-03-21 *10:03*
> * …
>
> I’m using the following log4j configuration
> {{<?xml version="1.0" encoding="UTF-8"?>}}
> {{<Configuration status="warn">}}
> {{ <Appenders>}}
> {{ <RollingFile name="app_log"
> filePattern="logs/app.%d\{yyyy-MM-dd_HH-mm}.log">}}
> {{ <PatternLayout>}}
> {{ <Pattern>%d\{DEFAULT} - %m%n</Pattern>}}
> {{ </PatternLayout>}}
> {{ <Policies>}}
> {{ <TimeBasedTriggeringPolicy modulate="true"/>}}
> {{ </Policies>}}
> {{ </RollingFile>}}
> {{ </Appenders>}}
> {{ <Loggers>}}
> {{ <Root level="info">}}
> {{ <AppenderRef ref="app_log" level="info"/>}}
> {{ </Root>}}
> {{ </Loggers>}}
> {{</Configuration>}}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
