[jira] [Created] (LOG4J2-2284) Logfile rolling broken with RollingFileAppender and TimeBasedTriggeringPolicy

["Hartmut Honisch (JIRA)" <ji...@apache.org>]

Hartmut Honisch created LOG4J2-2284:
---------------------------------------

             Summary: 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.11.0, 2.10.0
         Environment: Windows 10, Java 1.8.161
            Reporter: Hartmut Honisch


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>}}



--
This message was sent by Atlassian JIRA
(v7.6.3#76005)