Why ConditionEvaluationReportLoggingListener never invoked in failed context tests using ApplicationContextRunner?

Question

Expected behavior

As a spring-boot developer

• in order to diagnose failed context startup in tests using ApplicationContextRunner
• I need ConditionEvaluationReportLoggingListener to print report as documented in

https://docs.spring.io/spring-boot/docs/2.3.6.RELEASE/reference/htmlsingle/#boot-features-test-autoconfig

The runner can also be used to display the ConditionEvaluationReport. The report can be printed at INFO or DEBUG level. The following example shows how to use the ConditionEvaluationReportLoggingListener to print the report in auto-configuration tests.

@Test
public void autoConfigTest {
    ConditionEvaluationReportLoggingListener initializer = new ConditionEvaluationReportLoggingListener(
            LogLevel.INFO);
    ApplicationContextRunner contextRunner = new ApplicationContextRunner()
            .withInitializer(initializer).run((context) -> {
                    // Do something...
            });
}

In order to help me diagnose failures of test (in particular when context fails to be initialized), I need to get a report such as the following to understand whether my @ConditionalOnProperty logic is correct.

@Configuration
@ConditionalOnProperty(value= DynamicCatalogConstants.OPT_IN_PROPERTY)
@EnableConfigurationProperties
public class DynamicCatalogServiceAutoConfiguration {
[...]

20-11-2020 14:47:02.380 [main] DEBUG o.s.b.a.l.ConditionEvaluationReportLoggingListener.logAutoConfigurationReport - 


============================
CONDITIONS EVALUATION REPORT
============================


Positive matches:
-----------------

   DynamicCatalogServiceAutoConfiguration matched:
      - @ConditionalOnProperty (osbcmdb.dynamic-catalog.enabled) matched (OnPropertyCondition)


Negative matches:
-----------------

    None


Exclusions:
-----------

    None


Unconditional classes:
----------------------

    None

I'm using spring-boot 2.3.6.

Observed behavior

The condition report is not invoked when context fails to start

Instead of a condition report, only the following context init exception is displayed

20-11-2020 14:24:10.609 [main] WARN  o.s.c.a.AnnotationConfigApplicationContext.refresh - Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.support.BeanDefinitionOverrideException: Invalid bean definition with name 'dynamicCatalogService' defined in com.orange.oss.osbcmdb.catalog.DynamicCatalogServiceAutoConfigurationTest$SingleServiceDefinitionAnswerAutoConfig: Cannot register bean definition [Root bean: class [null]; scope=; abstract=false; lazyInit=null; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=dynamicCatalogServiceAutoConfigurationTest.SingleServiceDefinitionAnswerAutoConfig; factoryMethodName=dynamicCatalogService; initMethodName=null; destroyMethodName=(inferred); defined in com.orange.oss.osbcmdb.catalog.DynamicCatalogServiceAutoConfigurationTest$SingleServiceDefinitionAnswerAutoConfig] for bean 'dynamicCatalogService': There is already [Root bean: class [null]; scope=; abstract=false; lazyInit=null; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=dynamicCatalogServiceAutoConfiguration; factoryMethodName=dynamicCatalogService; initMethodName=null; destroyMethodName=(inferred); defined in com.orange.oss.osbcmdb.catalog.DynamicCatalogServiceAutoConfiguration] bound.


java.lang.IllegalStateException: Unstarted application context org.springframework.boot.test.context.assertj.AssertableApplicationContext[startupFailure=org.springframework.beans.factory.support.BeanDefinitionOverrideException] failed to start

    at org.springframework.boot.test.context.assertj.AssertProviderApplicationContextInvocationHandler.getStartedApplicationContext(AssertProviderApplicationContextInvocationHandler.java:156)
    at org.springframework.boot.test.context.assertj.AssertProviderApplicationContextInvocationHandler.invokeApplicationContextMethod(AssertProviderApplicationContextInvocationHandler.java:147)
    at org.springframework.boot.test.context.assertj.AssertProviderApplicationContextInvocationHandler.invoke(AssertProviderApplicationContextInvocationHandler.java:85)
    at com.sun.proxy.$Proxy20.getBean(Unknown Source)
    at com.orange.oss.osbcmdb.catalog.DynamicCatalogServiceAutoConfigurationTest.lambda$dynamicServiceLoadWhenOptInProperty$2(DynamicCatalogServiceAutoConfigurationTest.java:84)

Sample code:

    @Test
    void dynamicServiceLoadWhenOptInProperty() {
        ConditionEvaluationReportLoggingListener initializer = new ConditionEvaluationReportLoggingListener(LogLevel.INFO);
        ApplicationContextRunner contextRunner = new ApplicationContextRunner()
            .withInitializer(initializer)
            .withConfiguration(AutoConfigurations.of(
                SingleServiceDefinitionAnswerAutoConfig.class,
                DynamicCatalogServiceAutoConfiguration.class,
                MockedMaintenanceInfoFormatterServiceConfig.class
            ))
            .withPropertyValues(DynamicCatalogConstants.OPT_IN_PROPERTY + "=true");
        contextRunner.run(context -> {
            Catalog catalog = context.getBean(Catalog.class);
            assertThat(catalog.getServiceDefinitions()).isNotEmpty();

            assertThat(context).hasSingleBean(Catalog.class);
        });
    }

What I tried

The logging level is properly set to debug.

Stepping into the debugger, it seems that the ConditionEvaluationReportLoggingListener is never invoked for event notifications.

I however managed to manually trigger the condition report printed by invoking it explicitly with the debugger:

Should I submit an issue on the springboot repo ?

Answer 1

The limitation was acknowledged by the spring-boot team in https://github.com/spring-projects/spring-boot/issues/24235

Hopefully a future improvement will fix this problem.