[LOG4J2-999] RollingFileAppender only rotates when time is after rollover time, not on exact match

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: 2.2
• Fix Version/s: 2.5
• Component/s: Appenders

Environment

Linux CentOS 6.7, jdk7.0.57, Tomcat7.0.59

• Assignee: Remko Popma
• Reporter: Joan Balagueró
• Created: 24/Apr/15 11:45
• Updated: 24/Oct/15 19:35
• Resolved: 24/Oct/15 19:35

Description

I have this log4j.xml configuration file: http://www.grupoventus.com/download/log4j.xml
Relevant snippet:

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

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.