Skip to content

Commit c037e75

Browse files
jhoellerjhoeller
committed
Improve debug logging at BeanDefinitionReader and BeanFactory level
Issue: SPR-17090
1 parent 23bda9a commit c037e75

24 files changed

+177
-150
lines changed

‎spring-aop/src/main/java/org/springframework/aop/framework/CglibAopProxy.java‎

Lines changed: 21 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -157,8 +157,8 @@ public Object getProxy() {
157157

158158
@Override
159159
public Object getProxy(@Nullable ClassLoader classLoader) {
160-
if (logger.isDebugEnabled()) {
161-
logger.debug("Creating CGLIB proxy: target source is " + this.advised.getTargetSource());
160+
if (logger.isTraceEnabled()) {
161+
logger.trace("Creating CGLIB proxy: " + this.advised.getTargetSource());
162162
}
163163

164164
try {
@@ -810,24 +810,28 @@ public ProxyCallbackFilter(
810810
@Override
811811
public int accept(Method method) {
812812
if (AopUtils.isFinalizeMethod(method)) {
813-
logger.debug("Found finalize() method - using NO_OVERRIDE");
813+
logger.trace("Found finalize() method - using NO_OVERRIDE");
814814
return NO_OVERRIDE;
815815
}
816816
if (!this.advised.isOpaque() && method.getDeclaringClass().isInterface() &&
817817
method.getDeclaringClass().isAssignableFrom(Advised.class)) {
818-
if (logger.isDebugEnabled()) {
819-
logger.debug("Method is declared on Advised interface: " + method);
818+
if (logger.isTraceEnabled()) {
819+
logger.trace("Method is declared on Advised interface: " + method);
820820
}
821821
return DISPATCH_ADVISED;
822822
}
823823
// We must always proxy equals, to direct calls to this.
824824
if (AopUtils.isEqualsMethod(method)) {
825-
logger.debug("Found 'equals' method: " + method);
825+
if (logger.isTraceEnabled()) {
826+
logger.trace("Found 'equals' method: " + method);
827+
}
826828
return INVOKE_EQUALS;
827829
}
828830
// We must always calculate hashCode based on the proxy.
829831
if (AopUtils.isHashCodeMethod(method)) {
830-
logger.debug("Found 'hashCode' method: " + method);
832+
if (logger.isTraceEnabled()) {
833+
logger.trace("Found 'hashCode' method: " + method);
834+
}
831835
return INVOKE_HASHCODE;
832836
}
833837
Class<?> targetClass = this.advised.getTargetClass();
@@ -840,25 +844,25 @@ public int accept(Method method) {
840844
if (haveAdvice || !isFrozen) {
841845
// If exposing the proxy, then AOP_PROXY must be used.
842846
if (exposeProxy) {
843-
if (logger.isDebugEnabled()) {
844-
logger.debug("Must expose proxy on advised method: " + method);
847+
if (logger.isTraceEnabled()) {
848+
logger.trace("Must expose proxy on advised method: " + method);
845849
}
846850
return AOP_PROXY;
847851
}
848852
String key = method.toString();
849853
// Check to see if we have fixed interceptor to serve this method.
850854
// Else use the AOP_PROXY.
851855
if (isStatic && isFrozen && this.fixedInterceptorMap.containsKey(key)) {
852-
if (logger.isDebugEnabled()) {
853-
logger.debug("Method has advice and optimizations are enabled: " + method);
856+
if (logger.isTraceEnabled()) {
857+
logger.trace("Method has advice and optimizations are enabled: " + method);
854858
}
855859
// We know that we are optimizing so we can use the FixedStaticChainInterceptors.
856860
int index = this.fixedInterceptorMap.get(key);
857861
return (index + this.fixedInterceptorOffset);
858862
}
859863
else {
860-
if (logger.isDebugEnabled()) {
861-
logger.debug("Unable to apply any optimizations to advised method: " + method);
864+
if (logger.isTraceEnabled()) {
865+
logger.trace("Unable to apply any optimizations to advised method: " + method);
862866
}
863867
return AOP_PROXY;
864868
}
@@ -874,15 +878,15 @@ public int accept(Method method) {
874878
}
875879
Class<?> returnType = method.getReturnType();
876880
if (targetClass != null && returnType.isAssignableFrom(targetClass)) {
877-
if (logger.isDebugEnabled()) {
878-
logger.debug("Method return type is assignable from target type and " +
881+
if (logger.isTraceEnabled()) {
882+
logger.trace("Method return type is assignable from target type and " +
879883
"may therefore return 'this' - using INVOKE_TARGET: " + method);
880884
}
881885
return INVOKE_TARGET;
882886
}
883887
else {
884-
if (logger.isDebugEnabled()) {
885-
logger.debug("Method return type ensures 'this' cannot be returned - " +
888+
if (logger.isTraceEnabled()) {
889+
logger.trace("Method return type ensures 'this' cannot be returned - " +
886890
"using DISPATCH_TARGET: " + method);
887891
}
888892
return DISPATCH_TARGET;

‎spring-aop/src/main/java/org/springframework/aop/framework/JdkDynamicAopProxy.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -115,8 +115,8 @@ public Object getProxy() {
115115

116116
@Override
117117
public Object getProxy(@Nullable ClassLoader classLoader) {
118-
if (logger.isDebugEnabled()) {
119-
logger.debug("Creating JDK dynamic proxy: target source is " + this.advised.getTargetSource());
118+
if (logger.isTraceEnabled()) {
119+
logger.trace("Creating JDK dynamic proxy: " + this.advised.getTargetSource());
120120
}
121121
Class<?>[] proxiedInterfaces = AopProxyUtils.completeProxiedInterfaces(this.advised, true);
122122
findDefinedEqualsAndHashCodeMethods(proxiedInterfaces);

‎spring-aop/src/main/java/org/springframework/aop/framework/adapter/ThrowsAdviceInterceptor.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -136,8 +136,8 @@ private Method getExceptionHandler(Throwable exception) {
136136
exceptionClass = exceptionClass.getSuperclass();
137137
handler = this.exceptionHandlerMap.get(exceptionClass);
138138
}
139-
if (handler != null && logger.isDebugEnabled()) {
140-
logger.debug("Found handler for exception of type [" + exceptionClass.getName() + "]: " + handler);
139+
if (handler != null && logger.isTraceEnabled()) {
140+
logger.trace("Found handler for exception of type [" + exceptionClass.getName() + "]: " + handler);
141141
}
142142
return handler;
143143
}

‎spring-beans/src/main/java/org/springframework/beans/BeanUtils.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -511,8 +511,8 @@ public static PropertyEditor findEditorByConvention(@Nullable Class<?> targetTyp
511511
return (PropertyEditor) instantiateClass(editorClass);
512512
}
513513
catch (ClassNotFoundException ex) {
514-
if (logger.isDebugEnabled()) {
515-
logger.debug("No property editor [" + editorName + "] found for type " +
514+
if (logger.isTraceEnabled()) {
515+
logger.trace("No property editor [" + editorName + "] found for type " +
516516
targetType.getName() + " according to 'Editor' suffix convention");
517517
}
518518
unknownEditorTypes.add(targetType);

‎spring-beans/src/main/java/org/springframework/beans/factory/groovy/GroovyBeanDefinitionReader.java‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -236,6 +236,10 @@ public int loadBeanDefinitions(EncodedResource encodedResource) throws BeanDefin
236236
return this.standardXmlBeanDefinitionReader.loadBeanDefinitions(encodedResource);
237237
}
238238

239+
if (logger.isTraceEnabled()) {
240+
logger.trace("Loading Groovy bean definitions from " + encodedResource);
241+
}
242+
239243
Closure beans = new Closure(this) {
240244
@Override
241245
public Object call(Object[] args) {
@@ -265,7 +269,12 @@ public void setVariable(String name, Object value) {
265269
throw new BeanDefinitionParsingException(new Problem("Error evaluating Groovy script: " + ex.getMessage(),
266270
new Location(encodedResource.getResource()), null, ex));
267271
}
268-
return getRegistry().getBeanDefinitionCount() - countBefore;
272+
273+
int count = getRegistry().getBeanDefinitionCount() - countBefore;
274+
if (logger.isDebugEnabled()) {
275+
logger.debug("Loaded " + count + " bean definitions from " + encodedResource);
276+
}
277+
return count;
269278
}
270279

271280

‎spring-beans/src/main/java/org/springframework/beans/factory/support/AbstractAutowireCapableBeanFactory.java‎

Lines changed: 16 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -459,8 +459,8 @@ public void destroyBean(Object existingBean) {
459459
protected Object createBean(String beanName, RootBeanDefinition mbd, @Nullable Object[] args)
460460
throws BeanCreationException {
461461

462-
if (logger.isDebugEnabled()) {
463-
logger.debug("Creating instance of bean '" + beanName + "'");
462+
if (logger.isTraceEnabled()) {
463+
logger.trace("Creating instance of bean '" + beanName + "'");
464464
}
465465
RootBeanDefinition mbdToUse = mbd;
466466

@@ -496,8 +496,8 @@ protected Object createBean(String beanName, RootBeanDefinition mbd, @Nullable O
496496

497497
try {
498498
Object beanInstance = doCreateBean(beanName, mbdToUse, args);
499-
if (logger.isDebugEnabled()) {
500-
logger.debug("Finished creating instance of bean '" + beanName + "'");
499+
if (logger.isTraceEnabled()) {
500+
logger.trace("Finished creating instance of bean '" + beanName + "'");
501501
}
502502
return beanInstance;
503503
}
@@ -562,8 +562,8 @@ protected Object doCreateBean(final String beanName, final RootBeanDefinition mb
562562
boolean earlySingletonExposure = (mbd.isSingleton() && this.allowCircularReferences &&
563563
isSingletonCurrentlyInCreation(beanName));
564564
if (earlySingletonExposure) {
565-
if (logger.isDebugEnabled()) {
566-
logger.debug("Eagerly caching bean '" + beanName +
565+
if (logger.isTraceEnabled()) {
566+
logger.trace("Eagerly caching bean '" + beanName +
567567
"' to allow for resolving potential circular references");
568568
}
569569
addSingletonFactory(beanName, () -> getEarlyBeanReference(beanName, mbd, bean));
@@ -1417,8 +1417,8 @@ protected void autowireByName(
14171417
Object bean = getBean(propertyName);
14181418
pvs.add(propertyName, bean);
14191419
registerDependentBean(propertyName, beanName);
1420-
if (logger.isDebugEnabled()) {
1421-
logger.debug("Added autowiring by name from bean name '" + beanName +
1420+
if (logger.isTraceEnabled()) {
1421+
logger.trace("Added autowiring by name from bean name '" + beanName +
14221422
"' via property '" + propertyName + "' to bean named '" + propertyName + "'");
14231423
}
14241424
}
@@ -1468,8 +1468,8 @@ protected void autowireByType(
14681468
}
14691469
for (String autowiredBeanName : autowiredBeanNames) {
14701470
registerDependentBean(autowiredBeanName, beanName);
1471-
if (logger.isDebugEnabled()) {
1472-
logger.debug("Autowiring by type from bean name '" + beanName + "' via property '" +
1471+
if (logger.isTraceEnabled()) {
1472+
logger.trace("Autowiring by type from bean name '" + beanName + "' via property '" +
14731473
propertyName + "' to bean named '" + autowiredBeanName + "'");
14741474
}
14751475
}
@@ -1784,8 +1784,8 @@ protected void invokeInitMethods(String beanName, final Object bean, @Nullable R
17841784

17851785
boolean isInitializingBean = (bean instanceof InitializingBean);
17861786
if (isInitializingBean && (mbd == null || !mbd.isExternallyManagedInitMethod("afterPropertiesSet"))) {
1787-
if (logger.isDebugEnabled()) {
1788-
logger.debug("Invoking afterPropertiesSet() on bean with name '" + beanName + "'");
1787+
if (logger.isTraceEnabled()) {
1788+
logger.trace("Invoking afterPropertiesSet() on bean with name '" + beanName + "'");
17891789
}
17901790
if (System.getSecurityManager() != null) {
17911791
try {
@@ -1835,17 +1835,17 @@ protected void invokeCustomInitMethod(String beanName, final Object bean, RootBe
18351835
initMethodName + "' on bean with name '" + beanName + "'");
18361836
}
18371837
else {
1838-
if (logger.isDebugEnabled()) {
1839-
logger.debug("No default init method named '" + initMethodName +
1838+
if (logger.isTraceEnabled()) {
1839+
logger.trace("No default init method named '" + initMethodName +
18401840
"' found on bean with name '" + beanName + "'");
18411841
}
18421842
// Ignore non-existent default lifecycle methods.
18431843
return;
18441844
}
18451845
}
18461846

1847-
if (logger.isDebugEnabled()) {
1848-
logger.debug("Invoking init method '" + initMethodName + "' on bean with name '" + beanName + "'");
1847+
if (logger.isTraceEnabled()) {
1848+
logger.trace("Invoking init method '" + initMethodName + "' on bean with name '" + beanName + "'");
18491849
}
18501850

18511851
if (System.getSecurityManager() != null) {

‎spring-beans/src/main/java/org/springframework/beans/factory/support/AbstractBeanDefinitionReader.java‎

Lines changed: 18 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
package org.springframework.beans.factory.support;
1818

1919
import java.io.IOException;
20+
import java.util.Collections;
2021
import java.util.Set;
2122

2223
import org.apache.commons.logging.Log;
@@ -45,7 +46,7 @@
4546
* @since 11.12.2003
4647
* @see BeanDefinitionReaderUtils
4748
*/
48-
public abstract class AbstractBeanDefinitionReader implements EnvironmentCapable, BeanDefinitionReader {
49+
public abstract class AbstractBeanDefinitionReader implements BeanDefinitionReader, EnvironmentCapable {
4950

5051
/** Logger available to subclasses. */
5152
protected final Log logger = LogFactory.getLog(getClass());
@@ -182,11 +183,11 @@ public BeanNameGenerator getBeanNameGenerator() {
182183
@Override
183184
public int loadBeanDefinitions(Resource... resources) throws BeanDefinitionStoreException {
184185
Assert.notNull(resources, "Resource array must not be null");
185-
int counter = 0;
186+
int count = 0;
186187
for (Resource resource : resources) {
187-
counter += loadBeanDefinitions(resource);
188+
count += loadBeanDefinitions(resource);
188189
}
189-
return counter;
190+
return count;
190191
}
191192

192193
@Override
@@ -213,23 +214,21 @@ public int loadBeanDefinitions(String location, @Nullable Set<Resource> actualRe
213214
ResourceLoader resourceLoader = getResourceLoader();
214215
if (resourceLoader == null) {
215216
throw new BeanDefinitionStoreException(
216-
"Cannot import bean definitions from location [" + location + "]: no ResourceLoader available");
217+
"Cannot load bean definitions from location [" + location + "]: no ResourceLoader available");
217218
}
218219

219220
if (resourceLoader instanceof ResourcePatternResolver) {
220221
// Resource pattern matching available.
221222
try {
222223
Resource[] resources = ((ResourcePatternResolver) resourceLoader).getResources(location);
223-
int loadCount = loadBeanDefinitions(resources);
224+
int count = loadBeanDefinitions(resources);
224225
if (actualResources != null) {
225-
for (Resource resource : resources) {
226-
actualResources.add(resource);
227-
}
226+
Collections.addAll(actualResources, resources);
228227
}
229-
if (logger.isDebugEnabled()) {
230-
logger.debug("Loaded " + loadCount + " bean definitions from location pattern [" + location + "]");
228+
if (logger.isTraceEnabled()) {
229+
logger.trace("Loaded " + count + " bean definitions from location pattern [" + location + "]");
231230
}
232-
return loadCount;
231+
return count;
233232
}
234233
catch (IOException ex) {
235234
throw new BeanDefinitionStoreException(
@@ -239,25 +238,25 @@ public int loadBeanDefinitions(String location, @Nullable Set<Resource> actualRe
239238
else {
240239
// Can only load single resources by absolute URL.
241240
Resource resource = resourceLoader.getResource(location);
242-
int loadCount = loadBeanDefinitions(resource);
241+
int count = loadBeanDefinitions(resource);
243242
if (actualResources != null) {
244243
actualResources.add(resource);
245244
}
246-
if (logger.isDebugEnabled()) {
247-
logger.debug("Loaded " + loadCount + " bean definitions from location [" + location + "]");
245+
if (logger.isTraceEnabled()) {
246+
logger.trace("Loaded " + count + " bean definitions from location [" + location + "]");
248247
}
249-
return loadCount;
248+
return count;
250249
}
251250
}
252251

253252
@Override
254253
public int loadBeanDefinitions(String... locations) throws BeanDefinitionStoreException {
255254
Assert.notNull(locations, "Location array must not be null");
256-
int counter = 0;
255+
int count = 0;
257256
for (String location : locations) {
258-
counter += loadBeanDefinitions(location);
257+
count += loadBeanDefinitions(location);
259258
}
260-
return counter;
259+
return count;
261260
}
262261

263262
}

‎spring-beans/src/main/java/org/springframework/beans/factory/support/AbstractBeanFactory.java‎

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -245,13 +245,13 @@ protected <T> T doGetBean(final String name, @Nullable final Class<T> requiredTy
245245
// Eagerly check singleton cache for manually registered singletons.
246246
Object sharedInstance = getSingleton(beanName);
247247
if (sharedInstance != null && args == null) {
248-
if (logger.isDebugEnabled()) {
248+
if (logger.isTraceEnabled()) {
249249
if (isSingletonCurrentlyInCreation(beanName)) {
250-
logger.debug("Returning eagerly cached instance of singleton bean '" + beanName +
250+
logger.trace("Returning eagerly cached instance of singleton bean '" + beanName +
251251
"' that is not fully initialized yet - a consequence of a circular reference");
252252
}
253253
else {
254-
logger.debug("Returning cached instance of singleton bean '" + beanName + "'");
254+
logger.trace("Returning cached instance of singleton bean '" + beanName + "'");
255255
}
256256
}
257257
bean = getObjectForBeanInstance(sharedInstance, name, beanName, null);
@@ -385,8 +385,8 @@ else if (mbd.isPrototype()) {
385385
return convertedBean;
386386
}
387387
catch (TypeMismatchException ex) {
388-
if (logger.isDebugEnabled()) {
389-
logger.debug("Failed to convert bean '" + name + "' to required type '" +
388+
if (logger.isTraceEnabled()) {
389+
logger.trace("Failed to convert bean '" + name + "' to required type '" +
390390
ClassUtils.getQualifiedName(requiredType) + "'", ex);
391391
}
392392
throw new BeanNotOfRequiredTypeException(name, requiredType, bean.getClass());
@@ -1519,18 +1519,18 @@ protected Class<?> getTypeForFactoryBean(String beanName, RootBeanDefinition mbd
15191519
}
15201520
catch (BeanCreationException ex) {
15211521
if (ex.contains(BeanCurrentlyInCreationException.class)) {
1522-
if (logger.isDebugEnabled()) {
1523-
logger.debug("Bean currently in creation on FactoryBean type check: " + ex);
1522+
if (logger.isTraceEnabled()) {
1523+
logger.trace("Bean currently in creation on FactoryBean type check: " + ex);
15241524
}
15251525
}
15261526
else if (mbd.isLazyInit()) {
1527-
if (logger.isDebugEnabled()) {
1528-
logger.debug("Bean creation exception on lazy FactoryBean type check: " + ex);
1527+
if (logger.isTraceEnabled()) {
1528+
logger.trace("Bean creation exception on lazy FactoryBean type check: " + ex);
15291529
}
15301530
}
15311531
else {
1532-
if (logger.isInfoEnabled()) {
1533-
logger.info("Bean creation exception on non-lazy FactoryBean type check: " + ex);
1532+
if (logger.isDebugEnabled()) {
1533+
logger.debug("Bean creation exception on non-lazy FactoryBean type check: " + ex);
15341534
}
15351535
}
15361536
onSuppressedException(ex);

0 commit comments

Comments
 (0)