Spring-boot: Adding @EnableAutoConfiguration on an auto-configuration breaks ordering

[bcalmac]

The /actuator/health endpoint for our spring-boot application does not include the 'db' indicator and I tracked it down to DataSourceHealthIndicatorAutoConfiguration not seeing the dataSouce bean.

I have also attached the full log, but in this small snippet you can see that Liquibase and Mybatis see the Hikari dataSource just fine.

   DataSourceConfiguration.Hikari matched:
      - @ConditionalOnClass found required class 'com.zaxxer.hikari.HikariDataSource'; @ConditionalOnMissingClass did not find unwanted class (OnClassCondition)
      - @ConditionalOnProperty (spring.datasource.type=com.zaxxer.hikari.HikariDataSource) matched (OnPropertyCondition)
      - @ConditionalOnMissingBean (types: javax.sql.DataSource; SearchStrategy: all) did not find any beans (OnBeanCondition)
...
   LiquibaseAutoConfiguration matched:
      - @ConditionalOnClass found required classes 'liquibase.integration.spring.SpringLiquibase', 'liquibase.change.DatabaseChange'; @ConditionalOnMissingClass did not find unwanted class (OnClassCondition)
      - @ConditionalOnProperty (spring.liquibase.enabled) matched (OnPropertyCondition)
      - @ConditionalOnBean (types: javax.sql.DataSource; SearchStrategy: all) found bean 'dataSource' (OnBeanCondition)
...
   MybatisAutoConfiguration matched:
      - @ConditionalOnClass found required classes 'org.apache.ibatis.session.SqlSessionFactory', 'org.mybatis.spring.SqlSessionFactoryBean'; @ConditionalOnMissingClass did not find unwanted class (OnClassCondition)
      - @ConditionalOnBean (types: javax.sql.DataSource; SearchStrategy: all) found bean 'dataSource' (OnBeanCondition)
...
   DataSourceHealthIndicatorAutoConfiguration:
      Did not match:
         - @ConditionalOnBean (types: javax.sql.DataSource; SearchStrategy: all) did not find any beans of type javax.sql.DataSource (OnBeanCondition)
      Matched:
         - @ConditionalOnClass found required classes 'org.springframework.jdbc.core.JdbcTemplate', 'org.springframework.jdbc.datasource.lookup.AbstractRoutingDataSource'; @ConditionalOnMissingClass did not find unwanted class (OnClassCondition)
         - @ConditionalOnEnabledHealthIndicator management.health.defaults.enabled is considered true (OnEnabledHealthIndicatorCondition)

The data source configuration is standard:

spring:
  datasource:
    url: jdbc:postgresql://localhost:5432/ccp_product?currentSchema=product
    username: product
    password: ********
    driver-class-name: org.postgresql.Driver

Spring Boot Version: 2.0.5.RELEASE

This is a regression, the 'db' health indicator works fine in the version that I'm upgrading from, 1.5.10.RELEASE.

[wilkinsona]

It looks like something is causing the conditions on DataSourceHealthIndicatorAutoConfiguration to be evaluated too early. Unfortunately, I can’t tell what that is from the log. You could probably track it down with a breakpoint in OnBeanCondition. Alternatively, we could do so if we had a minimal sample that reproduces the problem.

[bcalmac]

All right, I put a breakpoint in OnBeanCondition and it looks like DataSourceHealthIndicatorAutoConfiguration is processed before DataSourceConfiguration$Hikari. LiquibaseAutoConfiguration comes after the latter and the dataSource is already available.

Here is the stack trace and configuration model whenDataSourceHealthIndicatorAutoConfiguration is evaluated:

• model-db-health-evaluation.txt
• stack-db-health-evaluation.txt

and then the same files when LiquibaseAutoConfiguration is evaluated:

• model-liquibase-evaluation.txt
• stack-liquibase-evaluation.txt

The notable difference is:

ConfigurationClass: beanName 'null', class path resource [org/springframework/boot/autoconfigure/jdbc/DataSourceConfiguration$Hikari.class],

vs

ConfigurationClass: beanName 'org.springframework.boot.autoconfigure.jdbc.DataSourceConfiguration$Hikari', class path resource [org/springframework/boot/autoconfigure/jdbc/DataSourceConfiguration$Hikari.class],

Is this enough for you to pinpoint the problem? Anything else I can do to help?

[philwebb]

It's hard to see anything obvious from the logs or the stack traces. DataSourceHealthIndicatorAutoConfiguration has @AutoConfigureAfter(DataSourceAutoConfiguration.class) so it shouldn't be evaluated until the datasource bean has been created.

@bcalmac Are you able to put together a small sample application that replicates the problem so we can try to debug it locally?

[wilkinsona]

I commented on this earlier when I re-labelled it and that comment now seems to have disappeared. Not sure what's happened there.

The summary of it was that the auto-configuration classes appear to be in the wrong order. The model files show DataSourceHealthIndicatorAutoConfiguration before DataSourceAutoConfiguration which, as Phil explains above is wrong. It looked to me like there might be a bug in AutoConfigurationSorter that's being triggered by the auto-configuration in the app. There were also some classes that looked like user configuration in slightly odd places: both after all the auto-configuration and some in the middle of it too.

It would be interesting to know what the input and output of AutoConfigurationSorter is. It would also be useful to remove some of the dependencies with auto-configuration from the app to minimise things and see when/if the problem stops occurring. Doing that will hopefully also make it possible to provide a sample that reproduces the problem.

[bcalmac]

I wasn't able to reproduce the problem on a basic spring-boot application with just a data source.

I'll debug AutoConfigurationSorter and then start peeling off auto-configuration dependencies. It may not be feasible to create a small sample of our app, I'll leave that as a last resort.

[bcalmac]

OK, this is ugly but interesting. We have a company-wide starter and its main configuration was annotated with @EnableAutoConfiguration. I agree, it shouldn't be, removing it fixes the problem!

But here's what happens: when ConfigurationClassParser.processConfigurationClass() is invoked for our MyCompanyStarterConfiguration, the @EnableAutoConfiguration annotation on it triggers a second auto-configuration round. This time, the DataSourceAutoConfiguration is not visible, but DataSourceHealthIndicatorAutoConfiguration is, so it goes in front. This recursive call messes up the order. AutoConfigurationSorter works fine. This is the stack trace when DataSourceHealthIndicatorAutoConfiguration gets inserted:

processConfigurationClass:249, ConfigurationClassParser (org.springframework.context.annotation) [3]
processImports:636, ConfigurationClassParser (org.springframework.context.annotation)
processImports:618, ConfigurationClassParser (org.springframework.context.annotation)
doProcessConfigurationClass:303, ConfigurationClassParser (org.springframework.context.annotation)
processConfigurationClass:245, ConfigurationClassParser (org.springframework.context.annotation) [2]
parse:194, ConfigurationClassParser (org.springframework.context.annotation)
doProcessConfigurationClass:296, ConfigurationClassParser (org.springframework.context.annotation)
processConfigurationClass:245, ConfigurationClassParser (org.springframework.context.annotation) [1]
processImports:636, ConfigurationClassParser (org.springframework.context.annotation)
lambda$processDeferredImportSelectors$2:566, ConfigurationClassParser (org.springframework.context.annotation)
accept:-1, 1912172027 (org.springframework.context.annotation.ConfigurationClassParser$$Lambda$174)
forEach:1257, ArrayList (java.util)
processDeferredImportSelectors:563, ConfigurationClassParser (org.springframework.context.annotation)
parse:188, ConfigurationClassParser (org.springframework.context.annotation)
processConfigBeanDefinitions:316, ConfigurationClassPostProcessor (org.springframework.context.annotation)
postProcessBeanDefinitionRegistry:233, ConfigurationClassPostProcessor (org.springframework.context.annotation)
invokeBeanDefinitionRegistryPostProcessors:271, PostProcessorRegistrationDelegate (org.springframework.context.support)
invokeBeanFactoryPostProcessors:91, PostProcessorRegistrationDelegate (org.springframework.context.support)
invokeBeanFactoryPostProcessors:694, AbstractApplicationContext (org.springframework.context.support)
refresh:532, AbstractApplicationContext (org.springframework.context.support)
refresh:140, ServletWebServerApplicationContext (org.springframework.boot.web.servlet.context)
refresh:780, SpringApplication (org.springframework.boot)
refreshContext:412, SpringApplication (org.springframework.boot)
run:333, SpringApplication (org.springframework.boot)
run:1277, SpringApplication (org.springframework.boot)
run:1265, SpringApplication (org.springframework.boot)
main:18, Application (com.clearcapital.panel)

Since this worked fine in 1.5, is it possible that the handling of multiple @EnableAutoConfiguration changed in 2.0?

Being no-op should be fine or we should get a WARN, I don't see a case when this would be intentional or beneficial. What do you think?

As a side note, the JMX actuator endpoints were also broken. The effects of the recursive auto-configuration are for all practical purposes unpredictable.

[wilkinsona]

That is interesting. Thanks. Armed with that knowledge, are you now able to create a minimal sample that reproduces the problem?

[bcalmac]

Certainly, I will.

[bcalmac]

All right, see https://github.com/bcalmac/autoconf-order

mvn test will fail because the dbHealthIndicator bean is missing. It can be fixed by removing @EnableAutoConfiguration from MyStarterConfiguration.

Also, you can switch in the parent POM to 1.5.16 and the test will always pass.

[wilkinsona]

Thank you, @bcalmac. I've reproduced the problem.

I believe the change in behaviour is related to the introduction of DeferredImportSelector.Group in Spring Framework 5.0. When the first @EnableAutoConfiguration is encountered, a group is created and the auto-configurations are selected and sorted. Processing of them then begins. During this processing, the second @EnableAutoConfiguration is found and the auto-configurations are selected. Crucially on this occasion they aren't sorted which is what causes the ordering to be incorrect. This is happening, I think, because a DeferredImportSelector can no longer be recursive.

@snicoll Can you please take a look at this from the Framework side of things?

[snicoll]

@wilkinsona Thanks, I confirm the regression in Spring Framework 5.0 as you've described and am working on a fix, see SPR-17351 for updates.

[snicoll]

Interestingly enough, something has changed in Spring Framework 5.1.x that breaks this setup as it should:

Caused by: org.springframework.beans.factory.parsing.BeanDefinitionParsingException: Configuration problem: A circular @Import has been detected: Illegal attempt by @Configuration class 'MyStarterConfiguration' to import class 'MyStarter' as 'MyStarter' is already present in the current import stack [MyStarterConfiguration->MyStarterConfiguration->MyStarter->MyApplication]
Offending resource: class path resource [io/github/bcalmac/autoconforder/starter/MyStarterConfiguration.class]
    at org.springframework.beans.factory.parsing.FailFastProblemReporter.error(FailFastProblemReporter.java:72) ~[spring-beans-5.1.1.BUILD-20181009.212318-28.jar:5.1.1.BUILD-SNAPSHOT]

I thought initially that this new exception was due to my changes as part of SPR-17351 but I can easily reproduce the exact same stack with an unchanged version of master.

As removing @EnableAutoConfiguration from the auto-configuration (which basically requires to load itself, hence the cycle) fixes the issue, I don't think there's much else we can do here.