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

Log file pollution when using the <include> in a conditional block

    XMLWordPrintable

Details

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Major Major
    • 1.5.5
    • 1.4.6
    • logback-classic
    • spring boot application 3.x.x

    Description

      We are migration from Logback 1.2.11 to 1.4.7 and stumbled upon some log pollution. When a <include> element is used the and it is not able to resolve the file two entries are added to the log.

      11:00:18,521 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@43ed0ff3 - Adding [file:/C:/dev/include_IS_UNDEFINED] to configuration watch list.
      11:00:18,522 |-WARN in ch.qos.logback.core.joran.action.IncludeAction - Failed to open [file:/C:/dev/include_IS_UNDEFINED] 

      This is correct as the variable is currently undefined and logback is not able to include it yet. So yes I would expect to see these statement in the log.

      However when placing an <include> element inside an <if> block I would not expect these statement to be included, as it should try to read the configuration.

      Reproduction configuration:

      <configuration debug="true">
          <!-- I placed the variable on the scope "system" as this is another bug. https://jira.qos.ch/browse/LOGBACK-1731 -->
          <variable scope="system" name="include" value="C:/dev/include.xml"/>
          <if condition='isDefined("include")'>
              <then>
                  <include file="${include}"/>
              </then>
          </if>
      </configuration> 

      Using the following configuration will result into the following log statements:

      11:15:44,779 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@6de54b40 - Adding [file:/C:/dev/include_IS_UNDEFINED] to configuration watch list.
      11:15:44,779 |-WARN in ch.qos.logback.core.joran.action.IncludeAction - Failed to open [file:/C:/dev/include_IS_UNDEFINED]
      11:15:45,593 |-INFO in ch.qos.logback.core.model.processor.conditional.IfModelHandler - Condition [isDefined("include")] evaluated to true on line 3 

      What we have noticed is that the IncludeAction is processed before the variable is set. I would expect that the <include> element is only processed when the condition has been met. 

      In the first line we see that <include> element is already being processed before the Condition or Variable have been processed.

      Now in the second line it is trying to open the file which it can't.

      On the third line we can see that the Condition actually is succeeding as the Variable has now been processed.

      Expectations:

      I would expect that the IncludeAction would take place in the order of definition:

      1. Variable "include" is set
      2. If condition is processed and matches
      3. File include is executed

      But what we see is the following:

      1. File include is executed
      2. Variable "include" is set
      3. If condition is processed and matches

      This would result into lesser log statements, 

      Attachments

        Activity

          People

            ceki Ceki Gülcü
            terryvdgriend Terry van der Griend
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: