Improve support for logback 1.3+ (#9018)

* Improve support for logback 1.3+

Logback 1.3.x+ changed the binary format for Configurators, and introduced a default one.

The issue is that when we call .configure on one, the JVM crashes as there is now an unexpected return value.

I cannot find a way of detecting and logging this issue (without some sort of reflection)

This change checks to see if the configurator we've detected is the default one added to logback in 1.3.x here

https://github.com/qos-ch/logback/blob/5ac98f440dabec45d8ab9b3519b2aa308f05793b/logback-classic/src/main/java/ch/qos/logback/classic/util/DefaultJoranConfigurator.java

And if it is, we ignore it.

This will not fix it for people using a Custom Configurator that they compile under Logback 1.3+, they will still see the crash with no warning.

But people upgrading to 1.3+ should see their application just run, and if they change their logback.xml emit debug with

```
<configuration debug="true">
```

They will see

```
12:55:21,222 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Skipping ch.qos.logback.classic.util.DefaultJoranConfigurator as it's assumed to be from an unsupported version of Logback
```

* Fix for Java 8

runtime/src/main/java/io/micronaut/logging/impl/LogbackUtils.java

@@ -39,6 +39,8 @@
  */
 public final class LogbackUtils {
 
+    private static final String DEFAULT_LOGBACK_13_PROGRAMMATIC_CONFIGURATOR = "ch.qos.logback.classic.util.DefaultJoranConfigurator";
+
     private LogbackUtils() {
     }
 
@@ -88,7 +90,7 @@ private static void configure(
         Supplier<URL> resourceSupplier
     ) {
         Configurator configurator = loadFromServiceLoader();
-        if (configurator != null) {
+        if (isSupportedConfigurator(context, configurator)) {
             context.getStatusManager().add(new InfoStatus("Using " + configurator.getClass().getName(), context));
             programmaticConfiguration(context, configurator);
         } else {
@@ -105,6 +107,17 @@ private static void configure(
         }
     }
 
+    private static boolean isSupportedConfigurator(LoggerContext context, Configurator configurator) {
+        if (configurator == null) {
+            return false;
+        }
+        if (DEFAULT_LOGBACK_13_PROGRAMMATIC_CONFIGURATOR.equals(configurator.getClass().getName())) {
+            context.getStatusManager().add(new InfoStatus("Skipping " + configurator.getClass().getName() + " as it's assumed to be from an unsupported version of Logback", context));
+            return false;
+        }
+        return true;
+    }
+
     /**
      * Taken from {@link ch.qos.logback.classic.util.ContextInitializer#autoConfig}.
      */

settings.gradle

@@ -70,6 +70,7 @@ include "test-suite-graal"
 include "test-suite-groovy"
 include "test-suite-groovy"
 include "test-suite-logback"
+include "test-suite-logback-14"
 include "test-suite-logback-external-configuration"
 include "test-utils"
 

test-suite-logback-14/build.gradle

@@ -0,0 +1,26 @@
+plugins {
+    id("io.micronaut.build.internal.convention-test-library")
+}
+
+description = "logback tests with a new version of logback than we support, just to check it runs.  Can be removed when we upgrade as part of 4.0.0"
+
+// Logback 1.4.x is Java 11+ compatible
+def logbackVersion = JavaVersion.current().isJava11Compatible() ? "1.4.6" : "1.3.6"
+
+dependencies {
+    testAnnotationProcessor(projects.injectJava)
+
+    testImplementation(libs.managed.micronaut.test.spock) {
+        exclude(group: "io.micronaut", module: "micronaut-aop")
+    }
+    testImplementation(projects.context)
+    testImplementation(projects.injectGroovy)
+
+    // Use a newer version of logback than we support
+    testImplementation("ch.qos.logback:logback-classic:${logbackVersion}")
+
+    testImplementation(projects.management)
+    testImplementation(projects.httpClient)
+
+    testRuntimeOnly(projects.httpServerNetty)
+}

test-suite-logback-14/src/test/groovy/io/micronaut/logback/LoggerConfigurationSpec.groovy

@@ -0,0 +1,31 @@
+package io.micronaut.logback
+
+import ch.qos.logback.classic.Level
+import ch.qos.logback.classic.Logger
+import io.micronaut.context.annotation.Property
+import io.micronaut.http.client.HttpClient
+import io.micronaut.http.client.annotation.Client
+import io.micronaut.test.extensions.spock.annotation.MicronautTest
+import jakarta.inject.Inject
+import org.slf4j.LoggerFactory
+import spock.lang.Specification
+
+@MicronautTest
+// Setting a level in a property forces a refresh, so the XML configuration is ignored. Without this in 3.8.x, the test fails.
+@Property(name = "logger.levels.set.by.property", value = "DEBUG")
+class LoggerConfigurationSpec extends Specification {
+
+    @Inject
+    @Client("/")
+    HttpClient client
+
+    void "if configuration is supplied, xml should be ignored"() {
+        given:
+        Logger fromXml = (Logger) LoggerFactory.getLogger("xml.config")
+        Logger fromProperties = (Logger) LoggerFactory.getLogger("set.by.property")
+
+        expect:
+        fromXml.level == Level.TRACE
+        fromProperties.level == Level.DEBUG
+    }
+}

test-suite-logback-14/src/test/groovy/io/micronaut/logback/LoggerEndpointSpec.groovy

@@ -0,0 +1,71 @@
+package io.micronaut.logback
+
+import ch.qos.logback.classic.Logger
+import ch.qos.logback.classic.spi.ILoggingEvent
+import ch.qos.logback.core.AppenderBase
+import io.micronaut.context.annotation.Property
+import io.micronaut.http.HttpRequest
+import io.micronaut.http.MediaType
+import io.micronaut.http.client.HttpClient
+import io.micronaut.http.client.annotation.Client
+import io.micronaut.logback.controllers.HelloWorldController
+import io.micronaut.test.extensions.spock.annotation.MicronautTest
+import jakarta.inject.Inject
+import org.slf4j.LoggerFactory
+import spock.lang.Issue
+import spock.lang.Specification
+
+@MicronautTest
+@Property(name = "logger.levels.io.micronaut.logback", value = "INFO")
+@Property(name = "endpoints.loggers.enabled", value = "true")
+@Property(name = "endpoints.loggers.sensitive", value = "false")
+@Property(name = "endpoints.loggers.write-sensitive", value = "false")
+@Issue("https://github.com/micronaut-projects/micronaut-core/issues/8679")
+class LoggerEndpointSpec extends Specification {
+
+    @Inject
+    @Client("/")
+    HttpClient client
+
+    void "logback configuration from properties is as expected"() {
+        when:
+        def response = client.toBlocking().retrieve("/loggers/io.micronaut.logback")
+
+        then:
+        response.contains("INFO")
+    }
+
+    void "logback can be configured"() {
+        given:
+        MemoryAppender appender = new MemoryAppender()
+        Logger l = (Logger) LoggerFactory.getLogger("io.micronaut.logback.controllers")
+        l.addAppender(appender)
+        appender.start()
+
+        when:
+        def response = client.toBlocking().retrieve("/", String)
+
+        then: 'response is as expected'
+        response == HelloWorldController.RESPONSE
+
+        and: 'no log message is emitted'
+        appender.events.empty
+
+        when: 'log level is changed to TRACE'
+        def body = '{ "configuredLevel": "TRACE" }'
+        def post = HttpRequest.POST("/loggers/io.micronaut.logback.controllers", body).contentType(MediaType.APPLICATION_JSON_TYPE)
+        client.toBlocking().exchange(post)
+
+        and:
+        response = client.toBlocking().retrieve("/", String)
+
+        then: 'response is as expected'
+        response == HelloWorldController.RESPONSE
+
+        and: 'log message is emitted'
+        appender.events == [HelloWorldController.LOG_MESSAGE]
+
+        cleanup:
+        appender.stop()
+    }
+}

test-suite-logback-14/src/test/groovy/io/micronaut/logback/LoggerLevelSpec.groovy

@@ -0,0 +1,46 @@
+package io.micronaut.logback
+
+import ch.qos.logback.classic.Logger
+import ch.qos.logback.classic.spi.ILoggingEvent
+import ch.qos.logback.core.AppenderBase
+import io.micronaut.context.annotation.Property
+import io.micronaut.http.HttpRequest
+import io.micronaut.http.MediaType
+import io.micronaut.http.client.HttpClient
+import io.micronaut.http.client.annotation.Client
+import io.micronaut.logback.controllers.HelloWorldController
+import io.micronaut.test.extensions.spock.annotation.MicronautTest
+import jakarta.inject.Inject
+import org.slf4j.LoggerFactory
+import spock.lang.Issue
+import spock.lang.Specification
+
+@MicronautTest
+@Property(name = "logger.levels.io.micronaut.logback.controllers", value = "TRACE")
+@Issue("https://github.com/micronaut-projects/micronaut-core/issues/8678")
+class LoggerLevelSpec extends Specification {
+
+    @Inject
+    @Client("/")
+    HttpClient client
+
+    void "logback can be configured via properties"() {
+        given:
+        MemoryAppender appender = new MemoryAppender()
+        Logger l = (Logger) LoggerFactory.getLogger("io.micronaut.logback.controllers")
+        l.addAppender(appender)
+        appender.start()
+
+        when:
+        def response = client.toBlocking().retrieve("/", String)
+
+        then: 'response is as expected'
+        response == HelloWorldController.RESPONSE
+
+        and: 'log message is emitted'
+        appender.events == [HelloWorldController.LOG_MESSAGE]
+
+        cleanup:
+        appender.stop()
+    }
+}

test-suite-logback-14/src/test/groovy/io/micronaut/logback/MemoryAppender.groovy

@@ -0,0 +1,17 @@
+package io.micronaut.logback
+
+import ch.qos.logback.classic.spi.ILoggingEvent
+import ch.qos.logback.core.AppenderBase
+import groovy.transform.CompileStatic
+import groovy.transform.PackageScope
+
+@PackageScope
+@CompileStatic
+class MemoryAppender extends AppenderBase<ILoggingEvent> {
+    List<String> events = []
+
+    @Override
+    protected void append(ILoggingEvent e) {
+        events << e.formattedMessage
+    }
+}

test-suite-logback-14/src/test/java/io/micronaut/logback/Application.java

@@ -0,0 +1,15 @@
+package io.micronaut.logback;
+
+import io.micronaut.runtime.Micronaut;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+public class Application {
+
+    private static final Logger LOG = LoggerFactory.getLogger(Application.class);
+
+    public static void main(String[] args) {
+        LOG.trace("starting the app");
+        Micronaut.run(Application.class, args);
+    }
+}

test-suite-logback-14/src/test/java/io/micronaut/logback/controllers/HelloWorldController.java

@@ -0,0 +1,21 @@
+package io.micronaut.logback.controllers;
+
+import io.micronaut.http.annotation.Controller;
+import io.micronaut.http.annotation.Get;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+@Controller
+public class HelloWorldController {
+
+    public static final String RESPONSE = "Hello world!";
+    public static final String LOG_MESSAGE = "inside hello world";
+
+    private static final Logger LOG = LoggerFactory.getLogger(HelloWorldController.class);
+
+    @Get
+    String index() {
+        LOG.trace(LOG_MESSAGE);
+        return RESPONSE;
+    }
+}

test-suite-logback-14/src/test/resources/logback.xml

@@ -0,0 +1,16 @@
+<configuration debug="true">
+
+    <!-- This should be ignored, as we have programmatic configuration -->
+    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
+        <!-- encoders are assigned the type
+             ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
+        <encoder>
+            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
+        </encoder>
+    </appender>
+
+    <root level="info">
+        <appender-ref ref="STDOUT" />
+    </root>
+    <logger name="xml.config" level="TRACE" />
+</configuration>