Uploaded image for project: 'logback'
  1. logback
  2. LOGBACK-158

DefaultTimeBasedFileNamingAndTriggeringPolicy should ignore early Joran call

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Unresolved
    • Icon: Minor Minor
    • None
    • None
    • logback-core
    • None

    Description

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

      Attachments

        Activity

          People

            logback-dev Logback dev list
            jhermann Juergen Hermann
            Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

              Created:
              Updated: