[logback-dev] [JIRA] Created: (LBCORE-196) DefaultTimeBasedFileNamingAndTriggeringPolicy should ignore early Joran call

[Juergen Hermann (JIRA)]

DefaultTimeBasedFileNamingAndTriggeringPolicy should ignore early Joran call
----------------------------------------------------------------------------

                 Key: LBCORE-196
                 URL: http://jira.qos.ch/browse/LBCORE-196
             Project: logback-core
          Issue Type: Bug
          Components: Rolling
    Affects Versions: 0.9.27
            Reporter: Juergen Hermann
            Assignee: Logback dev list
            Priority: Minor


Given a config snippet like this, where we _explicitely_ use the DefaultTimeBasedFileNamingAndTriggeringPolicy to cause the problem:

    <appender name="sandbox" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${catalina.base}/log/sandbox.log</file>
        <append>true</append>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${catalina.base}/log/sandbox.log.%d{yyyyMMdd}-000000</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy
                class="ch.qos.logback.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy"/>
        </rollingPolicy>
        <encoder>
            <pattern>%d{ISO8601} %9relative [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
    </appender> 

we get this stacktrace:
-INFO in ch.qos.logback.classic.joran.action.JMXConfiguratorAction - begin
-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [sandbox]
-ERROR in ch.qos.logback.core.joran.spi.Interpreter at 22:100 - RuntimeException in Action for tag [timeBasedFileNamingAndTriggeringPolicy] java.lang.NullPointerException
      at ch.qos.logback.core.rolling.TimeBasedFileNamingAndTriggeringPolicyBase.start(TimeBasedFileNamingAndTriggeringPolicyBase.java:44)
      at ch.qos.logback.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy.start(DefaultTimeBasedFileNamingAndTriggeringPolicy.java:32)
      at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:167)

Why is that? The code in TimeBasedRollingPolicy that sets the default implementation if none is given 
does so AFTER the "tbrp" member is set. Also, at the same location the setContext(context) and 
setTimeBasedRollingPolicy(this) calls are made, then start() is called on the TBFNATP (in a fully
pre-initialized state).

But before that and with an explicit policy configuration, Joran calls the start() method when the tag is 
closed on the newly created TBFNATP (see above stack trace), and that call must be ignored. That fact 
is suprising at first and should be documented, and the default TBFNATP should be augmented to be 
able to be used explicitely as above.

My own TBFNATP, derived from the default, thus has this code:

    @Override
    public void start() {
        if (tbrp == null) {
            // Containing policy did not initialize us yet!
            // This happens when Joran calls our start() when the config tag is closed.
            addInfo("Premature start ignored.");
            return;
        }
        super.start();
        ...

which prevents the problem. Maybe there could also be a more global solution that tells Joran 
that this is a nested, yet incomplete element and to not call start() in the first place, but let the
containing element do it.


-- 
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.qos.ch/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira