[LOG4J2-2766] TimeBasedTriggeringPolicy of RollingRandomAccessFile is not updated instantly

• Type: Bug
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 2.13.0
• Fix Version/s: 2.13.2
• Component/s: Appenders, Configurators, Reconfiguration
• Assignee: Ralph Goers
• Reporter: Heiko Schwanke
• Created: 24/Jan/20 10:18
• Updated: 14/Jan/21 10:35
• Resolved: 18/Apr/20 21:25

Description

If a RollingRandomAccessFile is updated with a new TimeBasedTriggeringPolicy during runtime, the new value is not updated until the original interval is reached once.

 

E.g. if logging is initialized with the rule to rotate every day and is later rerconfigured to rotate every hour, then you have to wait until the next day in order to get hourly rotated files.

This has to do with the ordering in the Update-Method of RollingRandomAccessFileManager. Before the new PatternProcessor is created the RollingRandomAccessFileManager initializes his TriggeringPolicy from the former PatternProcessor.

org.apache.logging.log4j.core.appender.rolling.RollingRandomAccessFileManager:

public void updateData(final Object data) {
  final FactoryData factoryData = (FactoryData) data;
  setRolloverStrategy(factoryData.getRolloverStrategy());
  setTriggeringPolicy(factoryData.getTriggeringPolicy()); // -> TimeBasedTriggeringPolicy.initialize will use old PatternProcessor
  setPatternProcessor(new PatternProcessor(factoryData.getPattern(), getPatternProcessor()));
}

org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy:

public void initialize(final RollingFileManager aManager) {
  this.manager = aManager;
  long current = aManager.getFileTime();
  if (current == 0) {
    current = System.currentTimeMillis();
  }  // LOG4J2-531: call getNextTime twice to force initialization of both prevFileTime and nextFileTime
  aManager.getPatternProcessor().getNextTime(current, interval, modulate);
  aManager.getPatternProcessor().setTimeBased(true);

  nextRolloverMillis = ThreadLocalRandom.current().nextLong(0, 1 + maxRandomDelayMillis)
        + aManager.getPatternProcessor().getNextTime(current, interval, modulate); // -> time comes from the old PatternProcessor (see above: RollingRandomAccessFileManager.updateData)
}

See also the attached simple testcase.

Issue Links

• is duplicated by: LOG4J2-2685 Automatic Reconfiguration fails in case of change in the triggeringpolicy
• relates to: LOG4J2-381 Changes in SizeBasedTriggeringPolicy has no effects when automatic reconfiguration is on.
• relates to: LOG4J2-1964 Dynamic reconfiguration does not work for filePattern of RollingFile
• relates to: LOG4J2-2457 RollingRandomAccessFileManager ignores new file patterns from programmatic reconfiguration