logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (LOG4J2-999) RollingFileAppender only rotates when time is after rollover time, not on exact match
Date Wed, 14 Oct 2015 02:02:07 GMT

     [ https://issues.apache.org/jira/browse/LOG4J2-999?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Remko Popma updated LOG4J2-999:
-------------------------------
    Fix Version/s: 2.5
          Summary: RollingFileAppender only rotates when time is after rollover time, not
on exact match  (was: Log4j2 Issue with RollingFileAppender rotation with AsyncLogger)

It turns out that this issue is not related to AsyncLoggers, so I am changing the title from
"Log4j2 Issue with RollingFileAppender rotation with AsyncLogger" to "RollingFileAppender
only rotates when time is after rollover time, not on exact match"

It turns out that a rollover is only triggered if the event time is _larger than_ the rollover
time (midnight in your case), and does not roll over when the event time is _exactly_ the
rollover time.

The documentation is a bit vague on when a rollover happens exactly. It says:

{quote}
The TimeBasedTriggeringPolicy causes a rollover once the date/time pattern no longer applies
to the active file.
{quote}

I think your example is a good argument that the current logic for {{TimeBasedTriggeringPolicy.isTriggeringEvent}}
should be changed from {{event.getTimeMillis() > nextRolloverMillis}} to  {{event.getTimeMillis()
>= nextRolloverMillis}}.


> RollingFileAppender only rotates when time is after rollover time, not on exact match
> -------------------------------------------------------------------------------------
>
>                 Key: LOG4J2-999
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-999
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.2
>         Environment: Linux CentOS 6.7, jdk7.0.57, Tomcat7.0.59
>            Reporter: Joan Balagueró
>            Assignee: Remko Popma
>            Priority: Critical
>             Fix For: 2.5
>
>
> I have this log4j.xml configuration file: http://www.grupoventus.com/download/log4j.xml
 
> Relevant snippet:
> {code}
> <RollingFile name="ACCESS_LOG" fileName="${sys:log.dir}vproxy_access"   
>       filePattern="${sys:log.dir}vproxy_access.%d{yyyy-MM-dd}" 
>       append="true" immediateFlush="false">
>   <PatternLayout>
>     <Pattern>%m%d{yyyy-MM-dd HH:mm:ss}%n</Pattern>
>   </PatternLayout>
>   <Policies>
>     <TimeBasedTriggeringPolicy/>
>   </Policies>
> </RollingFile>
> {code}
> There is an async logger called LOGGER_ACCESS that is using a RollingFileAppender named
ACCESS_LOG.
> We have sent an stress test against our application, about 500 simultaneous requests.
Every request appends a new line to the current log.
> At 00:00 log file was rotated, and now there are two logs (as expected): vproxy_acccess.2015-04-16
(the older) and vproxy_access (the current from today, day 17).
> But if we take a look to the old log file, we see this. Below the last two lines of my
log:
> 1,1429221599904,A,56,A,66,A,,190,A,S,5,S,2359,0000,2359,0,N,188.165.133.226,gzip,86,456,93,89,error.0011,2015-04-16
23:59:59
> 1,1429221599999,A,56,A,66,A,,190,A,S,5,S,2359,0000,2359,300000,S,,gzip,66342,456,1064,0,ok,2015-04-17
00:00:00
> The first request from 2015-04-17 has been included into the log from day 16. Just the
first one, the rest have been correctly appended to the vproxy_access log.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org


Mime
View raw message