You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Stephen Dawkins (JIRA)" <ji...@apache.org> on 2019/02/04 11:54:00 UTC
[jira] [Comment Edited] (LOG4J2-2284) Logfile rolling broken with
RollingFileAppender and TimeBasedTriggeringPolicy
[ https://issues.apache.org/jira/browse/LOG4J2-2284?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16759741#comment-16759741 ]
Stephen Dawkins edited comment on LOG4J2-2284 at 2/4/19 11:53 AM:
------------------------------------------------------------------
Tested with SNAPSHOT 2.11.2-20190203.193056-237. Looks better, it actually uses separate files, but it's still out by 1:
<removed, all wrong>
was (Author: elfarto):
Tested with SNAPSHOT 2.11.2-20190203.193056-237. Looks better, it actually uses separate files, but it's still out by 1:
{code:java}
2019-02-04 09:50:04,957 main DEBUG Now writing to logs/requests.log.2019-02-04-09-49 at 2019-02-04T09:50:04.956+0000
2019-02-04 09:50:04,946 DEBUG foo [main] hello: 2019-02-04 09:50:04
...
2019-02-04 09:51:00,009 Log4j2-TF-2-Scheduled-2 DEBUG Setting prev file time to 2019-02-04T09:51:00.000+0000
2019-02-04 09:51:00,010 Log4j2-TF-2-Scheduled-2 DEBUG Rolling logs/requests.log.2019-02-04-09-49
2019-02-04 09:51:00,012 Log4j2-TF-2-Scheduled-2 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1549273800000, prevFileTime=1549273860000
2019-02-04 09:51:00,013 Log4j2-TF-2-Scheduled-2 DEBUG Found 0 eligible files, max is 2147483647
2019-02-04 09:51:00,027 Log4j2-TF-2-Scheduled-2 DEBUG Formatting file name. useCurrentTime=false. currentFileTime=1549273800000, prevFileTime=1549273860000
2019-02-04 09:51:00,027 Log4j2-TF-2-Scheduled-2 DEBUG Formatting file name. useCurrentTime=true. currentFileTime=1549273800000, prevFileTime=1549273860000
2019-02-04 09:51:00,028 Log4j2-TF-2-Scheduled-2 DEBUG Now writing to logs/requests.log.2019-02-04-09-50 at 2019-02-04T09:51:00.028+0000
2019-02-04 09:51:00,029 Log4j2-TF-2-Scheduled-2 DEBUG Log4j2 ConfigurationScheduler Cron expression 0 * * ? * * * scheduled to fire again at 2019-02-04T09:52:00.000+0000
2019-02-04 09:51:04,962 DEBUG foo [main] hello: 2019-02-04 09:51:04{code}
I think the currentTime field should be removed completely. I've got a patch on LOG4J2-2483 which does that for a separate issue. You should only need two fields to track this, and currentTime is confusing matters.
> 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)