Hi,
I'm not sure when it started to happen, maybe even before 2.3.0, but it's easily reproduced with a minimal spring-boot-starter-web app and can be fixed by disabling BackgroundPreinitializer.
Could you check it please? Many thanks.
Comment From: philwebb
Can you provide a bit more information, I'm not that familiar with that part of the code? What's the warning message that you see when BackgroundPreinitializer is disabled? Do you know which class emits it?
Comment From: vseregin
Also reproduced in 2.3.1.
Here should be a warning: https://github.com/spring-projects/spring-framework/blob/master/spring-web/src/main/java/org/springframework/http/converter/json/Jackson2ObjectMapperBuilder.java#L866
Here is the property that you can toggle to see it: https://github.com/spring-projects/spring-boot/blob/master/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/BackgroundPreinitializer.java#L60
Just checked, 2.1.14 emits this warning regardless of whether this property was set or not.
Comment From: philwebb
Thanks for the extra info.
Comment From: wilkinsona
2.2 logs the expected warning:
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.2.8.RELEASE)
2020-07-01 12:19:55.553 INFO 96721 --- [ main] c.example.gh21897.Gh21897ApplicationKt : Starting Gh21897ApplicationKt on fulcrum.local with PID 96721 (/Users/awilkinson/dev/temp/gh-21897/build/classes/kotlin/main started by awilkinson in /Users/awilkinson/dev/temp/gh-21897)
2020-07-01 12:19:55.556 INFO 96721 --- [ main] c.example.gh21897.Gh21897ApplicationKt : No active profile set, falling back to default profiles: default
2020-07-01 12:20:09.583 WARN 96721 --- [kground-preinit] o.s.h.c.j.Jackson2ObjectMapperBuilder : For Jackson Kotlin classes support please add "com.fasterxml.jackson.module:jackson-module-kotlin" to the classpath
Comment From: wilkinsona
There's a race condition between logging performed during background pre-initialization and LogbackLoggingSystem removing its deny-all turbo filter. In 2.2, removing the filter wins but in 2.3 it does not. This change is due to 2.3 not having Hibernate Validator on the classpath. Adding a dependency on spring-boot-starter-validation to a 2.3 app slows down background pre-initialization enough for the removal of the filter to occur before the logging attempt is made. Further more, removing spring-boot-starter-validation from the dependencies of a 2.2 app is enough for the removal of the filter to lose the race and for the warnings to disappear.
Comment From: wilkinsona
Adding the deny-all filter and starting background preinitialisation are both triggered by ApplicationStartingEvent. Removing the deny-all filter is triggered by ApplicationEnvironmentPreparedEvent. To prevent logging during background preinitialisation from being denied, I think we'd need to trigger it in response to ApplicationEnvironmentPreparedEvent.
Comment From: wilkinsona
The specific pre-initialization of Jackson is pointless in most cases as it will have already been initialised via MessageConverterInitializer. It creates a AllEncompassingFormHttpMessageConverter which builds an ObjectMapper using Jackson2ObjectMapperBuilder. This means that removing preinitialization of Jackson alone does not fix the problem. Both MessageConverterInitializer and JacksonInitializer must be removed and this has a noticeable impact on startup time:
| Baseline | New | |
|---|---|---|
| 1.379 | 1.541 | |
| 1.345 | 1.564 | |
| 1.373 | 1.521 | |
| 1.386 | 1.534 | |
| 1.391 | 1.554 | |
| 1.378 | 1.533 | |
| 1.408 | 1.543 | |
| 1.377 | 1.542 | |
| 1.375 | 1.547 | |
| 1.368 | 1.580 | |
| Mean | 1.378 | 1.546 |
| Range | 0.063 | 0.059 |
An alternative is to move background preinitialization from application starting to environment prepared. This improves the situation but is still slower:
| Baseline | New | |
|---|---|---|
| 1.370 | 1.407 | |
| 1.401 | 1.435 | |
| 1.366 | 1.411 | |
| 1.367 | 1.407 | |
| 1.368 | 1.399 | |
| 1.369 | 1.409 | |
| 1.374 | 1.447 | |
| 1.360 | 1.407 | |
| 1.400 | 1.454 | |
| 1.397 | 1.456 | |
| Mean | 1.377 | 1.423 |
| Range | 0.041 | 0.057 |
Sticking with environment prepared and removing the duplicate initialisation of Jackson makes no noticeable difference.
Splitting the preinitialization so that message converter initialisation is done in environment prepared and everything else is done in application starting possibly closes the gap a little but it's still slower than before:
| Baseline | New | |
|---|---|---|
| 1.382 | 1.400 | |
| 1.376 | 1.425 | |
| 1.385 | 1.423 | |
| 1.433 | 1.423 | |
| 1.365 | 1.432 | |
| 1.377 | 1.406 | |
| 1.400 | 1.418 | |
| 1.395 | 1.446 | |
| 1.413 | 1.415 | |
| 1.413 | 1.414 | |
| Mean | 1.394 | 1.420 |
| Range | 0.068 | 0.046 |
Comment From: wilkinsona
We'd like to try configuring the builder with an empty list of modules. That will prevent it from configuring well-known modules so it won't trigger the single-time warning about Kotlin.
Comment From: wilkinsona
The builder with an empty list of modules does not help as the message converter initialiser, via creation of an AllEncompassingHttpMessageConverter, uses the builder in its default configuration.