Spring Boot with Webflux dependency breaks logging impl and forces DEBUG when using TestContext via AbstractTestNGSpringContextTests

[majones713]

ISSUE:

I have a test project which uses Spring Boot Gradle plugin. The project is not a running application but only used to execute set of testng tests, hence, doesn't require application.properties as its just tests. I'm using it this way:

public class CoreBaseTest extends AbstractTestNGSpringContextTests {}

I've been using RestTemplate for a while and now wanting to transition to WebClient.

When I added new WebFLux dependency to project:

implementation 'org.springframework.boot:spring-boot-starter-webflux'

and run my tests, all I see are a bunch of DEBUG logs being generated as if I set logging to DEBUG but I didn't. If I remove dependency, I see only INFO logs which is the normal expected behavior.

I have a log4j2.properties located in src/main/resources as well when using logger within classes. That working as expected but built-in spring classes are outputting DEBUG logs only when using webflux dependency. I tried setting logging level via

-Dlogging.level.org.springframework=INFO

but that doesn't work or help. Its as if webflux breaks AbstractTestNGSpringContextTests logging behavior.

My gradle plugin is as follows:

plugins {
	id "java"
	id "maven"
	id "io.freefair.lombok" version "5.1.0"
	id "org.springframework.boot" version "2.4.0" apply false
	id 'io.spring.dependency-management' version '1.0.10.RELEASE'
	id "com.jfrog.artifactory" version "4.15.2"
	id "maven-publish"
	id 'project-report'
}

My gradle dependencies is as follows:

dependencies {	
    implementation 'org.springframework:spring-test'
    implementation 'org.springframework:spring-context'
    implementation 'org.springframework:spring-web'
    implementation 'com.fasterxml.jackson.core:jackson-annotations'
    implementation 'org.springframework.boot:spring-boot-starter-webflux'
}

Again, if you remove webflux logging works as it did before but when you add somehow the behavior is broken. I'm using Java 11 as well.

DEBUG logs

[RemoteTestNG] detected TestNG version 7.3.0
14:54:45.719 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating CacheAwareContextLoaderDelegate from class [org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate]
14:54:45.736 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating BootstrapContext using constructor [public org.springframework.test.context.support.DefaultBootstrapContext(java.lang.Class,org.springframework.test.context.CacheAwareContextLoaderDelegate)]
14:54:45.772 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating TestContextBootstrapper for test class [com.farmers.test.css.api.security.clients.tests.SecurityBaseTest] from class [org.springframework.test.context.support.DefaultTestContextBootstrapper]
14:54:45.807 [main] DEBUG org.springframework.test.context.support.AbstractDelegatingSmartContextLoader - Delegating to AnnotationConfigContextLoader to process context configuration [ContextConfigurationAttributes@125290e5 declaringClass = 'com.farmers.test.css.api.core.basetest.CoreBaseTest', classes = '{class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}', locations = '{}', inheritLocations = true, initializers = '{}', inheritInitializers = true, name = [null], contextLoaderClass = 'org.springframework.test.context.ContextLoader'].
14:54:45.856 [main] DEBUG org.springframework.test.context.support.ActiveProfilesUtils - Could not find an 'annotation declaring class' for annotation type [org.springframework.test.context.ActiveProfiles] and class [com.farmers.test.css.api.security.clients.tests.SecurityBaseTest]
14:54:45.860 [main] DEBUG org.springframework.test.context.support.DefaultTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.web.ServletTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [javax/servlet/ServletContext]
14:54:45.862 [main] INFO org.springframework.test.context.support.DefaultTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@1e44b638, org.springframework.test.context.support.DependencyInjectionTestExecutionListener@7393222f, org.springframework.test.context.support.DirtiesContextTestExecutionListener@babafc2, org.springframework.test.context.event.EventPublishingTestExecutionListener@31add175, com.farmers.test.css.api.core.listeners.CoreCustomTestExecutionListener@ae3540e]
14:54:45.884 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating CacheAwareContextLoaderDelegate from class [org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate]
14:54:45.884 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating BootstrapContext using constructor [public org.springframework.test.context.support.DefaultBootstrapContext(java.lang.Class,org.springframework.test.context.CacheAwareContextLoaderDelegate)]
14:54:45.885 [main] DEBUG org.springframework.test.context.BootstrapUtils - Instantiating TestContextBootstrapper for test class [com.farmers.test.css.api.security.clients.tests.authn.AuthnTests] from class [org.springframework.test.context.support.DefaultTestContextBootstrapper]
14:54:45.885 [main] DEBUG org.springframework.test.context.support.AbstractDelegatingSmartContextLoader - Delegating to AnnotationConfigContextLoader to process context configuration [ContextConfigurationAttributes@74bf1791 declaringClass = 'com.farmers.test.css.api.core.basetest.CoreBaseTest', classes = '{class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}', locations = '{}', inheritLocations = true, initializers = '{}', inheritInitializers = true, name = [null], contextLoaderClass = 'org.springframework.test.context.ContextLoader'].
14:54:45.888 [main] DEBUG org.springframework.test.context.support.ActiveProfilesUtils - Could not find an 'annotation declaring class' for annotation type [org.springframework.test.context.ActiveProfiles] and class [com.farmers.test.css.api.security.clients.tests.authn.AuthnTests]
14:54:45.890 [main] DEBUG org.springframework.test.context.support.DefaultTestContextBootstrapper - Skipping candidate TestExecutionListener [org.springframework.test.context.web.ServletTestExecutionListener] due to a missing dependency. Specify custom listener classes or make the default listener classes and their required dependencies available. Offending class: [javax/servlet/ServletContext]
14:54:45.891 [main] INFO org.springframework.test.context.support.DefaultTestContextBootstrapper - Using TestExecutionListeners: [org.springframework.test.context.support.DirtiesContextBeforeModesTestExecutionListener@54504ecd, org.springframework.test.context.support.DependencyInjectionTestExecutionListener@38b27cdc, org.springframework.test.context.support.DirtiesContextTestExecutionListener@1339e7aa, org.springframework.test.context.event.EventPublishingTestExecutionListener@1fb669c3, com.farmers.test.css.api.core.listeners.CoreCustomTestExecutionListener@49c66ade]
14:54:45.938 [main] DEBUG org.springframework.test.context.support.DependencyInjectionTestExecutionListener - Performing dependency injection for test context [[DefaultTestContext@50d13246 testClass = SecurityBaseTest, testInstance = com.farmers.test.css.api.security.clients.tests.SecurityBaseTest@338c99c8, testMethod = [null], testException = [null], mergedContextConfiguration = [MergedContextConfiguration@2bd08376 testClass = SecurityBaseTest, locations = '{}', classes = '{class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{}', contextCustomizers = set[[empty]], contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader', parent = [null]], attributes = map[[empty]]]].
14:54:45.939 [main] DEBUG org.springframework.test.context.support.AbstractDelegatingSmartContextLoader - Delegating to AnnotationConfigContextLoader to load context from [MergedContextConfiguration@2bd08376 testClass = SecurityBaseTest, locations = '{}', classes = '{class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{}', contextCustomizers = set[[empty]], contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader', parent = [null]].
14:54:45.940 [main] DEBUG org.springframework.test.context.support.AbstractGenericContextLoader - Loading ApplicationContext for merged context configuration [[MergedContextConfiguration@2bd08376 testClass = SecurityBaseTest, locations = '{}', classes = '{class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}', contextInitializerClasses = '[]', activeProfiles = '{}', propertySourceLocations = '{}', propertySourceProperties = '{}', contextCustomizers = set[[empty]], contextLoader = 'org.springframework.test.context.support.DelegatingSmartContextLoader', parent = [null]]].
14:54:45.983 [main] DEBUG org.springframework.core.env.StandardEnvironment - Activating profiles []
14:54:45.983 [main] DEBUG org.springframework.test.context.support.AnnotationConfigContextLoader - Registering component classes: {class com.farmers.test.css.api.core.configuration.CorePropertiesConfiguration, class com.farmers.test.css.api.core.configuration.CoreRestTemplateConfiguration, class com.farmers.test.css.api.core.configuration.CoreWebClientConfiguration, class com.farmers.test.css.api.core.configuration.CoreEncryptionConfiguration, class com.farmers.test.css.api.core.configuration.CoreValidatorConfiguration, class com.farmers.test.css.api.core.configuration.CoreGenericConfiguration}
14:54:46.051 [main] DEBUG org.springframework.context.support.GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@1f010bf0
14:54:46.074 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'

[wilkinsona]

You have Logback on the classpath via spring-boot-starter-webflux's dependency on spring-boot-starter-logging. Logback uses debug level logging by default. If you don't want to use Logback, you should exclude spring-boot-starter-logging and rely on your Log4j2 dependencies (which are missing from your Gradle configuration above) instead.

[majones713]

@wilkinsona

I did that as well and it still didn't work, hence, why I raised this issue as its stuck in DEBUG:

implementation('org.springframework.boot:spring-boot-starter-webflux') {
		exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
	}

implementation('org.springframework.boot:spring-boot-starter-log4j2') {
		exclude group: 'org.apache.logging.log4j', module: 'log4j-slf4j-impl'
	}   

I excluded log4j-slf4j-impl as it complains if both log4j-to-slf4j and og4j-slf4j-impl are on classpath.

Here is dependency tree and you can see its absent and issue still persists:

org.springframework:spring-test ➡ 5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-jcl:5.3.1
 org.springframework:spring-context ➡ 5.3.1
 org.springframework:spring-aop:5.3.1
 org.springframework:spring-beans:5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-beans:5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-expression:5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-web ➡ 5.3.1
 org.springframework:spring-beans:5.3.1
 org.springframework:spring-core:5.3.1
 com.fasterxml.jackson.core:jackson-annotations ➡ 2.11.3
 com.google.code.gson:gson ➡ 2.8.6
 org.testng:testng:7.3.0
 com.beust:jcommander:1.78
 org.apache.ant:ant:1.10.3
 org.apache.ant:ant-launcher:1.10.3
 junit:junit:4.12 ➡ 4.13.1
 org.hamcrest:hamcrest-core:1.3 ➡ 2.2
 org.hamcrest:hamcrest:2.2
 com.google.inject:guice:4.2.2
 javax.inject:javax.inject:1
 aopalliance:aopalliance:1.0
 com.google.guava:guava:25.1-android
 com.google.code.findbugs:jsr305:3.0.2
 org.checkerframework:checker-compat-qual:2.0.0
 com.google.errorprone:error_prone_annotations:2.1.3
 com.google.j2objc:j2objc-annotations:1.1
 org.codehaus.mojo:animal-sniffer-annotations:1.14
 org.yaml:snakeyaml:1.21 ➡ 1.27
 com.farmers.css.api:css-api-core:1.0.18
 com.farmers.css.api:css-api-tdm-backbone-clients:1.0.7
 com.farmers.css.api:css-api-mulesoft-clients:1.0.25
 com.farmers.css.api:css-api-salesforce-clients:1.0.9
 com.farmers.css.util:css-encryption-utils:1.0.0
 org.glassfish:javax.el:3.0.0
 org.apache.commons:commons-lang3:3.11
 commons-validator:commons-validator:1.7
 commons-beanutils:commons-beanutils:1.9.4
 commons-logging:commons-logging:1.2
 commons-collections:commons-collections:3.2.2
 commons-digester:commons-digester:2.1
 commons-logging:commons-logging:1.2
 commons-collections:commons-collections:3.2.2
 org.springframework.boot:spring-boot-starter-webflux ➡ 2.4.0
 org.springframework.boot:spring-boot-starter:2.4.0
 org.springframework.boot:spring-boot:2.4.0
 org.springframework:spring-core:5.3.1
 org.springframework:spring-context:5.3.1
 org.springframework.boot:spring-boot-autoconfigure:2.4.0
 org.springframework.boot:spring-boot:2.4.0
 jakarta.annotation:jakarta.annotation-api:1.3.5
 org.springframework:spring-core:5.3.1
 org.yaml:snakeyaml:1.27
 org.springframework.boot:spring-boot-starter-json:2.4.0
 org.springframework.boot:spring-boot-starter:2.4.0
 org.springframework:spring-web:5.3.1
 com.fasterxml.jackson.core:jackson-databind:2.11.3
 com.fasterxml.jackson.core:jackson-annotations:2.11.3
 com.fasterxml.jackson.core:jackson-core:2.11.3
 com.fasterxml.jackson.datatype:jackson-datatype-jdk8:2.11.3
 com.fasterxml.jackson.core:jackson-core:2.11.3
 com.fasterxml.jackson.core:jackson-databind:2.11.3
 com.fasterxml.jackson.datatype:jackson-datatype-jsr310:2.11.3
 com.fasterxml.jackson.core:jackson-annotations:2.11.3
 com.fasterxml.jackson.core:jackson-core:2.11.3
 com.fasterxml.jackson.core:jackson-databind:2.11.3
 com.fasterxml.jackson.module:jackson-module-parameter-names:2.11.3
 com.fasterxml.jackson.core:jackson-core:2.11.3
 com.fasterxml.jackson.core:jackson-databind:2.11.3
 org.springframework.boot:spring-boot-starter-reactor-netty:2.4.0
 io.projectreactor.netty:reactor-netty-http:1.0.1
 io.netty:netty-codec-http:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-resolver:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-handler:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-resolver:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-codec-http2:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-handler:4.1.54.Final
 io.netty:netty-codec-http:4.1.54.Final
 io.netty:netty-resolver-dns:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-resolver:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-codec-dns:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-handler:4.1.54.Final
 io.netty:netty-transport-native-epoll:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-transport-native-unix-common:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.projectreactor.netty:reactor-netty-core:1.0.1
 io.netty:netty-handler:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-handler-proxy:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-codec-socks:4.1.54.Final
 io.netty:netty-common:4.1.54.Final
 io.netty:netty-buffer:4.1.54.Final
 io.netty:netty-transport:4.1.54.Final
 io.netty:netty-codec:4.1.54.Final
 io.netty:netty-codec-http:4.1.54.Final
 io.netty:netty-resolver-dns:4.1.53.Final ➡ 4.1.54.Final
 io.netty:netty-transport-native-epoll:4.1.53.Final ➡ 4.1.54.Final
 io.projectreactor:reactor-core:3.4.0
 org.reactivestreams:reactive-streams:1.0.3
 io.projectreactor:reactor-core:3.4.0
 org.springframework:spring-web:5.3.1
 org.springframework:spring-webflux:5.3.1
 org.springframework:spring-beans:5.3.1
 org.springframework:spring-core:5.3.1
 org.springframework:spring-web:5.3.1
 io.projectreactor:reactor-core:3.4.0
 org.springframework.boot:spring-boot-starter-log4j2 ➡ 2.4.0
 org.apache.logging.log4j:log4j-slf4j-impl:2.13.3
 org.slf4j:slf4j-api:1.7.25 ➡ 1.7.30
 org.apache.logging.log4j:log4j-api:2.13.3
 org.apache.logging.log4j:log4j-core:2.13.3
 org.apache.logging.log4j:log4j-api:2.13.3
 org.apache.logging.log4j:log4j-jul:2.13.3
 org.apache.logging.log4j:log4j-api:2.13.3
 org.slf4j:jul-to-slf4j:1.7.30
 org.slf4j:slf4j-api:1.7.30
 org.projectlombok:lombok:1.18.12

[majones713]

@wilkinsona It only happens in project that doesn't require application.properties but only when using AbstractTestNGSpringContextTests

[wilkinsona]

I did that as well and it still didn't work, hence, why I raised this issue as its stuck in DEBUG:

To avoid wasting time, please take the time to describe things you have already tried in the issue. Your original description makes no mention of this.

It only happens in project that doesn't require application.properties but only when using AbstractTestNGSpringContextTests

I don't know why that would be the case and from the fragments that you've provided thus far I don't think I'll be able to figure it out. If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.