Background preinitialisation may cause Jackson2ObjectMapperBuilder's Kotlin detection warning to be silently dropped

[vseregin]

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.

[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?

[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.

[philwebb]

Thanks for the extra info.

[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

[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.

[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.

[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

[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.

[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.