Interference when configuring log level and application of Logback config file after upgrading to Micronaut 3.8.0

Question

Observed behaviour

After upgrading Micronaut from 3.7.5 to 3.8.0, it seems like configuration of Logback framework "switches" right after application's start.

Background

We provide two config files logback.xml as well as logback-docker.xml, first one configures "plain" text logging, the second one JSON formatting of log messages. With local development the first one is usually applied, on productive systems the second one (via '-Dlogback.configurationFile=logback-docker.xml' JVM switch).

After upgrading to Micronaut 3.8.0 we observe the following log output with every deployment:

{"timestamp":"2023-01-04T07:24:50Z","message":"HHH000412: Hibernate ORM core version 5.6.14.Final","logger":"org.hibernate.Version","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:24:50Z","message":"HCANN000001: Hibernate Commons Annotations {5.1.2.Final}","logger":"org.hibernate.annotations.common.Version","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:24:50Z","message":"HHH000400: Using dialect: org.hibernate.dialect.H2Dialect","logger":"org.hibernate.dialect.Dialect","thread":"main","level_name":"INFO"}
2023-01-04T07:24:50Z [                  main] INFO  - Setting log level 'TRACE' for logger: 'org.zalando.logbook'
2023-01-04T07:24:51Z [                  main] INFO  - Startup completed in 1666ms. Server Running: http://localhost:8080
2023-01-04T07:24:51Z [                  main] INFO  - Micronaut version: 3.8.0
[...]

It seems like applied config file of Logback is getting switched after the first three log messages from JSON to plain text formatting ... as if switching from logback-docker.xml back to default logback.xml config file.

Switching back to version 3.7.5 the following expected log messages appear:

{"timestamp":"2023-01-04T07:27:37Z","message":"HHH000412: Hibernate ORM core version 5.6.11.Final","logger":"org.hibernate.Version","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:27:37Z","message":"HCANN000001: Hibernate Commons Annotations {5.1.2.Final}","logger":"org.hibernate.annotations.common.Version","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:27:37Z","message":"HHH000400: Using dialect: org.hibernate.dialect.H2Dialect","logger":"org.hibernate.dialect.Dialect","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:27:38Z","message":"Setting log level 'TRACE' for logger: 'org.zalando.logbook'","logger":"io.micronaut.logging.PropertiesLoggingLevelsConfigurer","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:27:38Z","message":"Startup completed in 1635ms. Server Running: http://localhost:8080","logger":"io.micronaut.runtime.Micronaut","thread":"main","level_name":"INFO"}
{"timestamp":"2023-01-04T07:27:38Z","message":"Micronaut version: 3.7.5","logger":"[...].Application","thread":"main","level_name":"INFO"}
[...]

Investigation shows that the observed "switch" of log message format ONLY happens when following configuration is set in Micronaut's application.yml (which usually is in our case):

[...]
logger:
  levels:
    org.zalando.logbook: TRACE
[...]

Removal of these three lines makes everything work as expected, also with Micronaut v3.8.0. (And of course this also makes log message "Setting log level 'TRACE' for logger: 'org.zalando.logbook'" disappear.)

So to me it seems there is some kind of interference of Micronaut's log level and further logging configuration of underlying Logback library.

So far I have investigated the circumstances.

Further background information

Currently we implement our code using Kotlin 1.8.0; behaviour does not change with 1.7.21.

Sample code to reproduce observed behaviour

To make it easier to reproduce the problem, I've set up a vanilla Micronaut project from scratch (using mn CLI), and added minimal code to make problem visible. Pushed this project to GitLab.

Further investigation

I think the problem stems from the fact that there are (at least) TWO ways to configure which Logback's config file to apply:

• Via Java VM's system property like so: java -Dlogback.configurationFile=MY-LOGBACK.XML [...]
• Via Micronaut's application.yaml file like so:

  logger:
    config: MY-LOGBACK.XML
  

Seems the second option has been introduced with Micronaut 3.8!

So it's easy to configure Logback framework in a CONTRADICTING way: The config given via VM property is valid up to the moment Micronaut's ApplicationContext is created, when application.yaml's config "takes over".

Let's reproduce this effect

Within our main method add log instructions before and after creation of ApplicationContext:

  fun main(args: Array<String>) {
      LOG.info { "BEFORE start of ApplicationContext" }
      val applicationContext = build()
          .args(*args)
          .banner(false)
          .start()
      LOG.info { "AFTER start of ApplicationContext" }
  }

Now we configure the "plain" logback.xml:

logger:
  config: logback.xml
  levels:
    foo: TRACE

Assembling the application via $ ./gradlew clean assemble and launching it with contradictory JVM property:

$ java -Dlogback.configurationFile=logback-timestamp-last.xml -jar build/libs/json-logging-0.1-all.jar 
json.logging.Application - BEFORE start of ApplicationContext | at 13:56:51.422
13:56:51.769 i.m.l.PropertiesLoggingLevelsConfigurer - Setting log level 'TRACE' for logger: 'foo'
13:56:51.936 io.micronaut.runtime.Micronaut - Startup completed in 500ms. Server Running: http://localhost:8080
13:56:51.938 json.logging.Application - AFTER start of ApplicationContext

We recognize a "switch" in log message format with ongoing setup of ApplicationContext, away from the one configured with JVM launch ("timestamp appended") "back" to the one from application.yaml ("timestamp prepended")!

Vice versa:

Configure the logback-timestamp-last.xml within application.yaml:

logger:
  config: logback-timestamp-last.xml
  levels:
    foo: TRACE

Re-assemble the application and launching it without any JVM system property yields an inverted "switch" of log message formats (from "timestamp prepended" to "timestamp appended"):

$ java -jar build/libs/json-logging-0.1-all.jar 
14:12:36.970 json.logging.Application - BEFORE start of ApplicationContext
i.m.l.PropertiesLoggingLevelsConfigurer - Setting log level 'TRACE' for logger: 'foo' | at 14:12:37.330
io.micronaut.runtime.Micronaut - Startup completed in 521ms. Server Running: http://localhost:8080 | at 14:12:37.505
json.logging.Application - AFTER start of ApplicationContext | at 14:12:37.507

Same with explicit configuration at JVM level:

$ java -Dlogback.configurationFile=logback.xml -jar build/libs/json-logging-0.1-all.jar 
14:13:32.432 json.logging.Application - BEFORE start of ApplicationContext
i.m.l.PropertiesLoggingLevelsConfigurer - Setting log level 'TRACE' for logger: 'foo' | at 14:13:32.823
io.micronaut.runtime.Micronaut - Startup completed in 550ms. Server Running: http://localhost:8080 | at 14:13:32.997
json.logging.Application - AFTER start of ApplicationContext | at 14:13:32.998

Interesting is the fact that these effects ONLY occur with additional configuration of log levels! If you comment out these two lines:

logger:
  config: logback-timestamp-last.xml
#  levels:
#    foo: TRACE

NONE of all the effects described above appear!

Q.E.D.

So in essence I came up with the following recommendation:

Do not configure Logback configuration files with Micronaut at JVM level, but with appropriate configuration item in Micronaut's application.yaml file!

BUT this interferes with log messages issued (by e.g. ORM tools) before ApplicationContext is set up! Example with log message from Hibernate:

[...]
2023-02-08T15:08:42Z [                  main] INFO  - HHH000400: Using dialect: org.hibernate.dialect.H2Dialect
{"timestamp":"2023-02-08T15:08:43Z","message":"Setting log level 'TRACE' for logger: 'org.zalando.logbook'","logger":"io.micronaut.logging.PropertiesLoggingLevelsConfigurer","thread":"main","level_name":"INFO"}
[...]

So improved recommendation:

If you use more than single logback.xml file, keep them in sync with JVM System Property CLI switch as well as Micronaut application.yml file evaluated with your Micronaut environment.

Conclusion

Option to configure custom Logback configuration file via application.yml file is also mentioned in current Micronaut documentation.

This

• does NOT affect log messages issued before final setup of Micronaut's ApplicationContext (like often the case with frameworks like OR mappers, even if they get set up in response to configs laid down in application.yml files), and
• it interferes with option to configure Logback config file via JVM CLI switch. To me it seems that both config options (JVM switch and application.yml) have to get synced to gain expected behaviour.

Answer 1

Update for micronaut-runtime:3.8.4 and above

With both

logger:
  levels:
    <Some package>: <Some logger level>

in application.yml and a logback.xml file, you'll get

io.micronaut.context.exceptions.BeanInstantiationException: 
Bean definition [io.micronaut.logging.PropertiesLoggingLevelsConfigurer] could not be loaded: Error instantiating bean of type  [io.micronaut.logging.PropertiesLoggingLevelsConfigurer]

Solution: Remove logger-config from application.yml

---

This may be related: My team too is experiencing issues related to logback when switching to MN 3.8.0 and Kotlin 1.8. Findings so far is that micronaut-bom-3.8.0.pom contains <logback.version>1.2.11</logback.version> which caused our apps to crash on startup. That was solved by adding

<logback.version>1.4.5</logback.version>

to our parent-POM properties-section. We already had this dependency:

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.4.5</version>
    <scope>runtime</scope>
</dependency>