CronTriggeringPolicy in RollingFileAppender is behind by one iteration

[Markus Dimmerling <Ma...@ppi.de>]

Hello everyone,

I have the following requirements for the migration of a custom log4j1 RollingFileAppender:

  *   Log every morning into a new directory with the current date as the name of the directory and part of the log file name
  *   If the size of a log file exceeds 100 MB, rollover to a new log file in the same directory

This is my current configuration:

    <RollingFile name="FileApp"
                 filePattern="${env:TRACE_PATH}}/trace/$${date:yyyy-MM-dd}/${sys:logger.serverId}.%d{yyyyMMdd}.trace.%i">
      <ThresholdFilter level="TRACE" onMatch="ACCEPT"/>
      <PatternLayout pattern="%d %-5p %- [%t] %c - %m%n"/>
      <Policies>
        <!--  create new trace file every day at 12:00 am -->
        <CronTriggeringPolicy schedule="0 0 0 ? * * *"/>
        <!--  max 100 MB per trace file -->
        <SizeBasedTriggeringPolicy size="100 MB"/>
      </Policies>
      <DirectWriteRolloverStrategy maxFiles="10"/>
    </RollingFile>


CronTriggeringPolicy and SizeBasedTriggeringPolicy seem straight forward, but it doesn't work as I excpected:
[cid:image001.png@01D8234D.C313D360]
Image Description: File System showing 3 directories. The names of the directories are 2022-02-16_1310, 2022-02-16_1315, and 2022-02-16_1320 and respective timestamps 16.02.2022 13:15:00, 16.02.2022 13:15:00, and 16.02.2022 13:25:00.

On the left you can see the name of the directory and on the right the last changed timestamps. The logs are empty, so the change timestamps are effectively created on timestamps.

This is based on a slightly different configuration compared to the configuration above. For shorter feedback loops this should log every 5 minutes:
<RollingFile name="FileApp"  filePattern="${env:TRACE_PATH}}/trace/$${ date:yyyy-MM-dd_HHmm}/${sys:logger.serverId}.%d{yyyyMMddHHmm}.trace.%i">
<CronTriggeringPolicy schedule="0 5,10,15,20,25,30,35,40,45,50,55,0 * ? * * *"/>

However you can see that the creation date of the directories is 5 minutes later than the name suggests. I.e. The log with the name 2022-02-16_1315 is created at 16.02.2022 13:20:00.
I restarted the server at 13:12. So the first log writes to the 1310 directory. That works as expected. But then at 13:15:00 another (empty) log file is created in the 1310 directory. The first log is empty except 4 short lines of log and not even 1 KB, so it's not because of the size. The next log is created at 13:20, but also with the wrong name. So all in all it's behind by one step. This also happens with daily logs.

I debugged the code in the CronTriggeringPolicy and that confirms these numbers. The PatternProcessor uses the "currentFileTime" or "prevFileTime". Both are initialized with "cronExpression.getPrevFireTime(new Date())" in CronTriggeringPolicy. So far these times seem to be correct. After a rollover the RollingFileManager sets these dates with parameters from CronTriggeringPolicy. prevFileTime is now a newly calculated "cronExpression.getPrevFireTime(new Date())" and currentFileTime is set to "lastRollDate" which is still the same from the initialization, because it only gets updated after a rollover. Depending on evaluateOnStartup it's either intialized to the getPrevFireTime from the beginning or "cronExpression.getPrevFireTime(new Date(this.manager.getFileTime()))". Both resulting in the same time in my case. (I also tested it with both states). That means both prevFileTime and currentFile are not the correct time for the first rollover.
Now after the first rollover lastRollDate is set to the fireTime of the cron scheduler. But that is now. So the next rollover will also be behind by 5 minutes.

(For transparency sake: There is also an empty directory named 2022-02-16_1312 created. But we can ignore that, because that's just a problem because the different time accuracies. [5-minute vs. 1 minute] It wouldn't happen with daily logs, which I only care about.)

I also tried a SizedBased Trigger like this:
<Policies>
      <OnStartupTriggeringPolicy minSize="0"/>
      <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
      <SizeBasedTriggeringPolicy size="100 MB"/>
    </Policies>

But that doesn't seem to create an empty log at the start of the day.


I'm not sure if this is a bug, or I'm using a weird configuration. I would assume that I'm not the only one using a CronTriggeringPolicy to create daily logs. Does anyone else have these problems?
Thanks a lot for your help,
Markus