Logback Variable Substitution does not work as expected

[arolfes]

Hello @stuartwdouglas ,

I want to use the logback variable substitution feature. Unfortunately it does not work as expected.

I created an example project here

Example Class with logging

package org.acme;

import javax.ws.rs.GET;
import javax.ws.rs.Path;
import javax.ws.rs.Produces;
import javax.ws.rs.core.MediaType;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Path("/hello")
public class GreetingResource {

    private final Logger log = LoggerFactory.getLogger(GreetingResource.class);

    @GET
    @Produces(MediaType.TEXT_PLAIN)
    public String hello() {
      log.debug("Hello Logback Debug Level");
      log.info("Hello Logback Info Level");
      log.warn("Hello Logback Warn Level");
      return "Hello from RESTEasy";
    }
}

logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="false">
  <appender name="Appender" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>
        %black(%d{ISO8601}) [%blue(%t)] %highlight(%-5level)[ traceId=%X{traceId} spanId=%X{spanId} ] %yellow(%C{1}): %msg%n%throwable
      </Pattern>
    </layout>
  </appender>

  <if condition='property("QUARKUS_PROFILE").contains("production")'>
    <then>
      <root>
        <level value="WARN"/>
        <appender-ref ref="Appender"/>
      </root>
    </then>
    <else>
      <root>
        <level value="DEBUG"/>
        <appender-ref ref="Appender"/>
      </root>
    </else>
  </if>
</configuration>

log messages

11:42:10,387 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
11:42:10,389 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender$$delayed]
11:42:10,390 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [Appender]
11:42:10,397 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - This appender no longer admits a layout as a sub-component, set an encoder instead.
11:42:10,397 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
11:42:10,397 |-WARN in ch.qos.logback.core.ConsoleAppender$$delayed[Appender] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
11:42:10,465 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - ROOT level set to DEBUG
11:42:10,465 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [Appender] to Logger[ROOT]
11:42:10,465 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.

2022-12-15 11:42:10,824 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: quarkus-logback-janino 1.0.0-SNAPSHOT on JVM (powered by Quarkus 2.14.3.Final) started in 2.411s. Listening on: http://localhost:8080
2022-12-15 11:42:10,827 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: Profile dev activated. Live Coding activated.
2022-12-15 11:42:10,827 [Quarkus Main Thread] INFO [ traceId= spanId= ] i.q.b.r.Timing: Installed features: [cdi, logging-logback, resteasy, smallrye-context-propagation, vertx]
2022-12-15 11:42:18,623 [executor-thread-0] INFO [ traceId= spanId= ] o.a.GreetingResource: Hello Logback Info Level
2022-12-15 11:42:18,623 [executor-thread-0] WARN [ traceId= spanId= ] o.a.GreetingResource: Hello Logback Warn Level

As you can see, logback sets the root logger to debug, but the loglevel debug is not printed

I don't understand why this happens. Can you explain what I did wrong?