Skip to content

Commit 997dd3e

Browse files
sbrannensbrannen
committed
Revise logging in the TestContext framework
For a Spring Boot test, Logback logs at DEBUG level by default until Spring Boot's logging infrastructure has a chance to take control, and this can result in a considerable amount of INFO and DEBUG output. It's not the number of lines that causes an issue. Rather, it's the amount of information in each line that can become overwhelming, especially when the MergedContextConfiguration is complex. The main reason for lengthy DEBUG logging in a Spring Boot test is that Spring Boot's ImportsContextCustomizer implements toString() which results in logging of the fully qualified class names of all imported configuration classes. In an example using @WebMvcTest, this resulted in logging of 27 imported classes twice. However, the lists of registered TestExecutionListener, ContextCustomizerFactory, and ContextCustomizer implementations are also logged separately, and that adds quite a bit of noise at DEBUG level. This commit addresses these issues and simultaneously completely revises logging within the Spring TestContext Framework (TCF). - Numerous log statements are now logged at TRACE level instead of DEBUG. - Numerous log statements now have two modes. When logging at TRACE level, fully qualified class names (or the results of invoking toString() on related components) are included. When logging at DEBUG level, simple names of classes are logged and the results of invoking toString() on related components are omitted. - toString() implementations in TCF components are now based on the newly introduced SimpleValueStyler for ToStringCreator. The combination of the above changes greatly reduces the amount of DEBUG logging output in the TCF, but users can still access complete details by switching to TRACE level logging. Closes gh-29229
1 parent f16366e commit 997dd3e

32 files changed

+335
-195
lines changed

‎spring-test/src/main/java/org/springframework/test/context/BootstrapUtils.java

+3-3
Original file line numberDiff line numberDiff line change
@@ -82,7 +82,7 @@ static BootstrapContext createBootstrapContext(Class<?> testClass) {
8282
ClassUtils.forName(className, BootstrapUtils.class.getClassLoader());
8383
Constructor<? extends BootstrapContext> constructor =
8484
clazz.getConstructor(Class.class, CacheAwareContextLoaderDelegate.class);
85-
logger.debug(LogMessage.format("Instantiating BootstrapContext using constructor [%s]", constructor));
85+
logger.trace(LogMessage.format("Instantiating BootstrapContext using constructor [%s]", constructor));
8686
return BeanUtils.instantiateClass(constructor, testClass, cacheAwareContextLoaderDelegate);
8787
}
8888
catch (Throwable ex) {
@@ -97,7 +97,7 @@ private static CacheAwareContextLoaderDelegate createCacheAwareContextLoaderDele
9797
try {
9898
clazz = (Class<? extends CacheAwareContextLoaderDelegate>)
9999
ClassUtils.forName(className, BootstrapUtils.class.getClassLoader());
100-
logger.debug(LogMessage.format("Instantiating CacheAwareContextLoaderDelegate from class [%s]", className));
100+
logger.trace(LogMessage.format("Instantiating CacheAwareContextLoaderDelegate from class [%s]", className));
101101
return BeanUtils.instantiateClass(clazz, CacheAwareContextLoaderDelegate.class);
102102
}
103103
catch (Throwable ex) {
@@ -151,7 +151,7 @@ static TestContextBootstrapper resolveTestContextBootstrapper(BootstrapContext b
151151
if (clazz == null) {
152152
clazz = resolveDefaultTestContextBootstrapper(testClass);
153153
}
154-
logger.debug(LogMessage.format("Instantiating TestContextBootstrapper for test class [%s] from class [%s]",
154+
logger.trace(LogMessage.format("Instantiating TestContextBootstrapper for test class [%s] from class [%s]",
155155
testClass.getName(), clazz.getName()));
156156
TestContextBootstrapper testContextBootstrapper =
157157
BeanUtils.instantiateClass(clazz, TestContextBootstrapper.class);

‎spring-test/src/main/java/org/springframework/test/context/ContextConfigurationAttributes.java

+9-7
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2021 the original author or authors.
2+
* Copyright 2002-2022 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -23,6 +23,8 @@
2323

2424
import org.springframework.context.ApplicationContextInitializer;
2525
import org.springframework.core.annotation.AnnotationAttributes;
26+
import org.springframework.core.style.DefaultToStringStyler;
27+
import org.springframework.core.style.SimpleValueStyler;
2628
import org.springframework.core.style.ToStringCreator;
2729
import org.springframework.lang.Nullable;
2830
import org.springframework.util.Assert;
@@ -368,15 +370,15 @@ public int hashCode() {
368370
*/
369371
@Override
370372
public String toString() {
371-
return new ToStringCreator(this)
372-
.append("declaringClass", this.declaringClass.getName())
373-
.append("classes", ObjectUtils.nullSafeToString(this.classes))
374-
.append("locations", ObjectUtils.nullSafeToString(this.locations))
373+
return new ToStringCreator(this, new DefaultToStringStyler(new SimpleValueStyler()))
374+
.append("declaringClass", this.declaringClass)
375+
.append("classes", this.classes)
376+
.append("locations", this.locations)
375377
.append("inheritLocations", this.inheritLocations)
376-
.append("initializers", ObjectUtils.nullSafeToString(this.initializers))
378+
.append("initializers", this.initializers)
377379
.append("inheritInitializers", this.inheritInitializers)
378380
.append("name", this.name)
379-
.append("contextLoaderClass", this.contextLoaderClass.getName())
381+
.append("contextLoaderClass", this.contextLoaderClass)
380382
.toString();
381383
}
382384

‎spring-test/src/main/java/org/springframework/test/context/MergedContextConfiguration.java

+10-8
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,8 @@
2424

2525
import org.springframework.context.ApplicationContext;
2626
import org.springframework.context.ApplicationContextInitializer;
27+
import org.springframework.core.style.DefaultToStringStyler;
28+
import org.springframework.core.style.SimpleValueStyler;
2729
import org.springframework.core.style.ToStringCreator;
2830
import org.springframework.lang.Nullable;
2931
import org.springframework.util.Assert;
@@ -495,16 +497,16 @@ public int hashCode() {
495497
*/
496498
@Override
497499
public String toString() {
498-
return new ToStringCreator(this)
500+
return new ToStringCreator(this, new DefaultToStringStyler(new SimpleValueStyler()))
499501
.append("testClass", this.testClass)
500-
.append("locations", ObjectUtils.nullSafeToString(this.locations))
501-
.append("classes", ObjectUtils.nullSafeToString(this.classes))
502-
.append("contextInitializerClasses", ObjectUtils.nullSafeToString(this.contextInitializerClasses))
503-
.append("activeProfiles", ObjectUtils.nullSafeToString(this.activeProfiles))
504-
.append("propertySourceLocations", ObjectUtils.nullSafeToString(this.propertySourceLocations))
505-
.append("propertySourceProperties", ObjectUtils.nullSafeToString(this.propertySourceProperties))
502+
.append("locations", this.locations)
503+
.append("classes", this.classes)
504+
.append("contextInitializerClasses", this.contextInitializerClasses)
505+
.append("activeProfiles", this.activeProfiles)
506+
.append("propertySourceLocations", this.propertySourceLocations)
507+
.append("propertySourceProperties", this.propertySourceProperties)
506508
.append("contextCustomizers", this.contextCustomizers)
507-
.append("contextLoader", nullSafeClassName(this.contextLoader))
509+
.append("contextLoader", (this.contextLoader != null ? this.contextLoader.getClass() : null))
508510
.append("parent", this.parent)
509511
.toString();
510512
}

‎spring-test/src/main/java/org/springframework/test/context/TestContextAnnotationUtils.java

+5-3
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,8 @@
3131
import org.springframework.core.annotation.MergedAnnotations;
3232
import org.springframework.core.annotation.MergedAnnotations.SearchStrategy;
3333
import org.springframework.core.annotation.RepeatableContainers;
34+
import org.springframework.core.style.DefaultToStringStyler;
35+
import org.springframework.core.style.SimpleValueStyler;
3436
import org.springframework.core.style.ToStringCreator;
3537
import org.springframework.lang.Nullable;
3638
import org.springframework.test.context.NestedTestConfiguration.EnclosingConfiguration;
@@ -585,9 +587,9 @@ public Set<T> findAllLocalMergedAnnotations() {
585587
*/
586588
@Override
587589
public String toString() {
588-
return new ToStringCreator(this)
589-
.append("rootDeclaringClass", this.rootDeclaringClass.getName())
590-
.append("declaringClass", this.declaringClass.getName())
590+
return new ToStringCreator(this, new DefaultToStringStyler(new SimpleValueStyler()))
591+
.append("rootDeclaringClass", this.rootDeclaringClass)
592+
.append("declaringClass", this.declaringClass)
591593
.append("annotation", this.annotation)
592594
.toString();
593595
}

‎spring-test/src/main/java/org/springframework/test/context/aot/AotTestContextInitializersCodeGenerator.java

+2-2
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ private CodeBlock generateContextInitializersMappingCode() {
123123
code.addStatement("$T map = new $T<>()", CONTEXT_INITIALIZER_SUPPLIER_MAP, HashMap.class);
124124
this.initializerClassMappings.forEach((className, testClasses) -> {
125125
List<String> testClassNames = testClasses.stream().map(Class::getName).toList();
126-
logger.debug(LogMessage.format(
126+
logger.trace(LogMessage.format(
127127
"Generating mapping from AOT context initializer supplier [%s] to test classes %s",
128128
className.reflectionName(), testClassNames));
129129
testClassNames.forEach(testClassName ->
@@ -146,7 +146,7 @@ private CodeBlock generateContextInitializerClassesMappingCode() {
146146
code.addStatement("$T map = new $T<>()", CONTEXT_INITIALIZER_CLASS_MAP, HashMap.class);
147147
this.initializerClassMappings.forEach((className, testClasses) -> {
148148
List<String> testClassNames = testClasses.stream().map(Class::getName).toList();
149-
logger.debug(LogMessage.format(
149+
logger.trace(LogMessage.format(
150150
"Generating mapping from AOT context initializer class [%s] to test classes %s",
151151
className.reflectionName(), testClassNames));
152152
testClassNames.forEach(testClassName ->

‎spring-test/src/main/java/org/springframework/test/context/cache/AotMergedContextConfiguration.java

+5-3
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@
1919
import java.util.Collections;
2020

2121
import org.springframework.context.ApplicationContextInitializer;
22+
import org.springframework.core.style.DefaultToStringStyler;
23+
import org.springframework.core.style.SimpleValueStyler;
2224
import org.springframework.core.style.ToStringCreator;
2325
import org.springframework.lang.Nullable;
2426
import org.springframework.test.context.CacheAwareContextLoaderDelegate;
@@ -82,9 +84,9 @@ public int hashCode() {
8284

8385
@Override
8486
public String toString() {
85-
return new ToStringCreator(this)
86-
.append("testClass", getTestClass().getName())
87-
.append("contextInitializerClass", this.contextInitializerClass.getName())
87+
return new ToStringCreator(this, new DefaultToStringStyler(new SimpleValueStyler()))
88+
.append("testClass", getTestClass())
89+
.append("contextInitializerClass", this.contextInitializerClass)
8890
.append("original", this.original)
8991
.toString();
9092
}

‎spring-test/src/main/java/org/springframework/test/context/cache/DefaultCacheAwareContextLoaderDelegate.java

+13-6
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,6 @@
2323
import org.springframework.context.ApplicationContextInitializer;
2424
import org.springframework.context.ConfigurableApplicationContext;
2525
import org.springframework.context.support.GenericApplicationContext;
26-
import org.springframework.core.log.LogMessage;
2726
import org.springframework.lang.Nullable;
2827
import org.springframework.test.annotation.DirtiesContext.HierarchyMode;
2928
import org.springframework.test.context.ApplicationContextFailureProcessor;
@@ -108,8 +107,8 @@ public ApplicationContext loadContext(MergedContextConfiguration mergedContextCo
108107
else {
109108
context = loadContextInternal(mergedContextConfiguration);
110109
}
111-
if (logger.isDebugEnabled()) {
112-
logger.debug("Storing ApplicationContext [%s] in cache under key %s".formatted(
110+
if (logger.isTraceEnabled()) {
111+
logger.trace("Storing ApplicationContext [%s] in cache under key %s".formatted(
113112
System.identityHashCode(context), mergedContextConfiguration));
114113
}
115114
this.contextCache.put(mergedContextConfiguration, context);
@@ -135,8 +134,8 @@ public ApplicationContext loadContext(MergedContextConfiguration mergedContextCo
135134
}
136135
}
137136
else {
138-
if (logger.isDebugEnabled()) {
139-
logger.debug("Retrieved ApplicationContext [%s] from cache with key %s".formatted(
137+
if (logger.isTraceEnabled()) {
138+
logger.trace("Retrieved ApplicationContext [%s] from cache with key %s".formatted(
140139
System.identityHashCode(context), mergedContextConfiguration));
141140
}
142141
}
@@ -198,7 +197,15 @@ protected ApplicationContext loadContextInAotMode(AotMergedContextConfiguration
198197
() -> "Failed to load AOT ApplicationContextInitializer for test class [%s]"
199198
.formatted(testClass.getName()));
200199
ContextLoader contextLoader = getContextLoader(aotMergedConfig);
201-
logger.info(LogMessage.format("Loading ApplicationContext in AOT mode for %s", aotMergedConfig.getOriginal()));
200+
201+
if (logger.isTraceEnabled()) {
202+
logger.trace("Loading ApplicationContext for AOT runtime for " + aotMergedConfig.getOriginal());
203+
}
204+
else if (logger.isDebugEnabled()) {
205+
logger.debug("Loading ApplicationContext for AOT runtime for test class " +
206+
aotMergedConfig.getTestClass().getName());
207+
}
208+
202209
if (!((contextLoader instanceof AotContextLoader aotContextLoader) &&
203210
(aotContextLoader.loadContextForAotRuntime(aotMergedConfig.getOriginal(), contextInitializer)
204211
instanceof GenericApplicationContext gac))) {

‎spring-test/src/main/java/org/springframework/test/context/jdbc/MergedSqlConfig.java

+4-2
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2021 the original author or authors.
2+
* Copyright 2002-2022 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -21,6 +21,8 @@
2121

2222
import org.springframework.core.annotation.AnnotationAttributes;
2323
import org.springframework.core.annotation.AnnotationUtils;
24+
import org.springframework.core.style.DefaultToStringStyler;
25+
import org.springframework.core.style.SimpleValueStyler;
2426
import org.springframework.core.style.ToStringCreator;
2527
import org.springframework.jdbc.datasource.init.ScriptUtils;
2628
import org.springframework.lang.Nullable;
@@ -210,7 +212,7 @@ ErrorMode getErrorMode() {
210212
*/
211213
@Override
212214
public String toString() {
213-
return new ToStringCreator(this)
215+
return new ToStringCreator(this, new DefaultToStringStyler(new SimpleValueStyler()))
214216
.append("dataSource", this.dataSource)
215217
.append("transactionManager", this.transactionManager)
216218
.append("transactionMode", this.transactionMode)

‎spring-test/src/main/java/org/springframework/test/context/jdbc/SqlScriptsTestExecutionListener.java

+11-7
Original file line numberDiff line numberDiff line change
@@ -247,9 +247,13 @@ private void executeSqlScripts(
247247
}
248248

249249
MergedSqlConfig mergedSqlConfig = new MergedSqlConfig(sql.config(), testContext.getTestClass());
250-
if (logger.isDebugEnabled()) {
251-
logger.debug(String.format("Processing %s for execution phase [%s] and test context %s.",
252-
mergedSqlConfig, executionPhase, testContext));
250+
if (logger.isTraceEnabled()) {
251+
logger.trace("Processing %s for execution phase [%s] and test context %s"
252+
.formatted(mergedSqlConfig, executionPhase, testContext));
253+
}
254+
else if (logger.isDebugEnabled()) {
255+
logger.debug("Processing merged @SqlConfig attributes for execution phase [%s] and test class [%s]"
256+
.formatted(executionPhase, testContext.getTestClass().getName()));
253257
}
254258

255259
String[] scripts = getScripts(sql, testContext.getTestClass(), testContext.getTestMethod(), classLevel);
@@ -265,7 +269,7 @@ private void executeSqlScripts(
265269
ResourceDatabasePopulator populator = createDatabasePopulator(mergedSqlConfig);
266270
populator.setScripts(scriptResources.toArray(new Resource[0]));
267271
if (logger.isDebugEnabled()) {
268-
logger.debug("Executing SQL scripts: " + ObjectUtils.nullSafeToString(scriptResources));
272+
logger.debug("Executing SQL scripts: " + scriptResources);
269273
}
270274

271275
String dsName = mergedSqlConfig.getDataSource();
@@ -372,9 +376,9 @@ private String detectDefaultScript(Class<?> testClass, Method testMethod, boolea
372376
ClassPathResource classPathResource = new ClassPathResource(resourcePath);
373377

374378
if (classPathResource.exists()) {
375-
if (logger.isInfoEnabled()) {
376-
logger.info(String.format("Detected default SQL script \"%s\" for test %s [%s]",
377-
prefixedResourcePath, elementType, elementName));
379+
if (logger.isDebugEnabled()) {
380+
logger.debug("Detected default SQL script \"%s\" for test %s [%s]"
381+
.formatted(prefixedResourcePath, elementType, elementName));
378382
}
379383
return prefixedResourcePath;
380384
}

‎spring-test/src/main/java/org/springframework/test/context/junit4/SpringJUnit4ClassRunner.java

+4-3
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2019 the original author or authors.
2+
* Copyright 2002-2022 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -135,8 +135,9 @@ private static void ensureSpringRulesAreNotPresent(Class<?> testClass) {
135135
*/
136136
public SpringJUnit4ClassRunner(Class<?> clazz) throws InitializationError {
137137
super(clazz);
138-
if (logger.isDebugEnabled()) {
139-
logger.debug("SpringJUnit4ClassRunner constructor called with [" + clazz + "]");
138+
if (logger.isTraceEnabled()) {
139+
logger.trace("SpringJUnit4ClassRunner constructor called with [%s]"
140+
.formatted((clazz != null ? clazz.getName() : null)));
140141
}
141142
ensureSpringRulesAreNotPresent(clazz);
142143
this.testContextManager = createTestContextManager(clazz);

‎spring-test/src/main/java/org/springframework/test/context/junit4/statements/SpringRepeat.java

+3-3
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2002-2015 the original author or authors.
2+
* Copyright 2002-2022 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -77,8 +77,8 @@ public SpringRepeat(Statement next, Method testMethod, int repeat) {
7777
@Override
7878
public void evaluate() throws Throwable {
7979
for (int i = 0; i < this.repeat; i++) {
80-
if (this.repeat > 1 && logger.isInfoEnabled()) {
81-
logger.info(String.format("Repetition %d of test %s#%s()", (i + 1),
80+
if (this.repeat > 1 && logger.isTraceEnabled()) {
81+
logger.trace(String.format("Repetition %d of test %s#%s()", (i + 1),
8282
this.testMethod.getDeclaringClass().getSimpleName(), this.testMethod.getName()));
8383
}
8484
this.next.evaluate();

‎spring-test/src/main/java/org/springframework/test/context/support/AbstractContextLoader.java

+6-6
Original file line numberDiff line numberDiff line change
@@ -255,20 +255,20 @@ protected String[] generateDefaultLocations(Class<?> clazz) {
255255
ClassPathResource classPathResource = new ClassPathResource(resourcePath);
256256
if (classPathResource.exists()) {
257257
String prefixedResourcePath = ResourceUtils.CLASSPATH_URL_PREFIX + SLASH + resourcePath;
258-
if (logger.isInfoEnabled()) {
259-
logger.info(String.format("Detected default resource location \"%s\" for test class [%s]",
258+
if (logger.isDebugEnabled()) {
259+
logger.debug(String.format("Detected default resource location \"%s\" for test class [%s]",
260260
prefixedResourcePath, clazz.getName()));
261261
}
262262
return new String[] {prefixedResourcePath};
263263
}
264-
else if (logger.isDebugEnabled()) {
265-
logger.debug(String.format("Did not detect default resource location for test class [%s]: " +
264+
else if (logger.isTraceEnabled()) {
265+
logger.trace(String.format("Did not detect default resource location for test class [%s]: " +
266266
"%s does not exist", clazz.getName(), classPathResource));
267267
}
268268
}
269269

270-
if (logger.isInfoEnabled()) {
271-
logger.info(String.format("Could not detect default resource locations for test class [%s]: " +
270+
if (logger.isDebugEnabled()) {
271+
logger.debug(String.format("Could not detect default resource locations for test class [%s]: " +
272272
"no resource found for suffixes %s.", clazz.getName(), ObjectUtils.nullSafeToString(suffixes)));
273273
}
274274

0 commit comments

Comments
 (0)