[LOG4J2-1474] CronTriggeringPolicy raise exception and fail to rollover log file when evaluateOnStartup is true.

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.6.2
• Fix Version/s: 2.8
• Component/s: Core

Environment

mac osx capiton/jvm 1.7/log4j-core 2.6.2

• Flags: Important
• Assignee: Gary D. Gregory
• Reporter: yin mingjun
• Created: 25/Jul/16 10:57
• Updated: 04/Jan/17 06:48
• Resolved: 07/Dec/16 03:10

Description

I am migrating my project from log1.x to log2.x, and I was using DailyRollingFileAppender before, and now I am trying to use RollingFileAppender instead it.

what i am doing is:
1. write a config file, with RollingFile's config, and use CronTriggeringPolicy config log file to roll over at middle-night.
2. also set it's CronTriggeringPolicy's evaluateOnStartup=true, require check roll over at start time.
3. I touch my log file to an older time, check it is working alright.
my touch command is:
touch -t 1607220101 biz-pubsvc-service.log

then i start my project, then I got an InvocationTargetException exception...........

>>>> I then trace into the log4j2's source file, find the exception is caused by CronTriggeringPolicy's initialize method:

    public void initialize(RollingFileManager aManager) {
        this.manager = aManager;
        Date nextDate = new Date(this.manager.getFileTime());
        this.nextRollDate = this.cronExpression.getNextValidTimeAfter(nextDate);
        if(this.checkOnStartup && this.nextRollDate.getTime() < System.currentTimeMillis()) {
            this.rollover(); >>> here, call rollover, need this.future
        }

        this.future = this.configuration.getScheduler().scheduleWithCron(this.cronExpression, new CronTriggeringPolicy.CronTrigger());  >>> here assign this.future first time
    }

we also refer CronTriggeringPolicy's rollover method's code:

    private void rollover() {
        this.manager.getPatternProcessor().setPrevFileTime(this.nextRollDate.getTime());
        this.manager.rollover();
        Date fireDate = this.future.getFireTime(); >>> raise null pointer exception here !!! 
        Calendar cal = Calendar.getInstance();
        cal.setTime(fireDate);
        cal.add(13, -1);
        this.nextRollDate = cal.getTime();
    }

I think this BUG is easy to fix up by moving [ this.future = ...] 's assignment just before the call of [ this.rollover(); ].

thanks.

Yin Mingjun

PS1: my log4j2.xml config file -------------------------------------------------------

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="warn">
  <appenders>
    <RollingFile name="myFile" fileName="biz-pubsvc-service.log" filePattern="biz-pubsvc-service.log.%d{yyyy-MM-dd}" append="true">
      <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss,SSS}] %-5p [%t] %c{2} - %m%n"/>
      <CronTriggeringPolicy schedule="0 0 0 * * ?" evaluateOnStartup="true"/>
    </RollingFile>

    <Console name="myConsole" target="SYSTEM_OUT">
      <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss,SSS}] %-5p [%t] %c{2} - %m%n"/>
    </Console>

  </appenders>
  <loggers>
    <root level="trace">
      <appender-ref ref="myConsole"/>
      <appender-ref ref="myFile"/>
    </root>
  </loggers>
</configuration>

PS2: the raising exception's call stack ----------------------------------------

2016-07-25 18:30:25,910 main ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile. java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:606)
	at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:132)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:918)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:858)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:850)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:479)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.initialize(AbstractConfiguration.java:219)
	at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:231)
	at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:496)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:566)
	at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:582)
	at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:217)

Issue Links

• Is contained by: LOG4J2-1653 CronTriggeringPolicy uses wrong naming and produces NPE
• is related to: LOG4J2-1653 CronTriggeringPolicy uses wrong naming and produces NPE