Improve context-related logging on web startup

rstoyanchev · rstoyanchev · commit 14d0fee86c20 · 2018-07-25T17:50:03.000-04:00
Sample output at TRACE:
```
DispatcherServlet - Initializing Servlet 'org.springframework.web.servlet.DispatcherServlet-7a8c8dcf'
AnnotationConfigWebApplicationContext - Refreshing WebApplicationContext for namespace 'org.springframework.web.servlet.DispatcherServlet-7a8c8dcf-servlet', started on Wed Jul 25 17:46:38 EDT 2018
AnnotationConfigWebApplicationContext - Registering [org.springframework.web.servlet.mvc.method.annotation.RequestPartIntegrationTests$CommonsMultipartResolverTestConfig]
AnnotationConfigWebApplicationContext - No 'messageSource' bean, using [Empty MessageSource]
AnnotationConfigWebApplicationContext - No 'applicationEventMulticaster' bean, using [SimpleApplicationEventMulticaster]
AnnotationConfigWebApplicationContext - No 'lifecycleProcessor' bean, using [DefaultLifecycleProcessor]
...
DispatcherServlet - Initialization completed in 3361 ms
```

Issue: SPR-16946
diff --git a/spring-context/src/main/java/org/springframework/context/support/AbstractApplicationContext.java b/spring-context/src/main/java/org/springframework/context/support/AbstractApplicationContext.java
@@ -585,7 +585,12 @@ protected void prepareRefresh() {
 		this.active.set(true);
 
 		if (logger.isDebugEnabled()) {
-			logger.debug("Refreshing " + this);
+			if (logger.isTraceEnabled()) {
+				logger.trace("Refreshing " + this);
+			}
+			else {
+				logger.debug("Refreshing " + getDisplayName());
+			}
 		}
 
 		// Initialize any placeholder property sources in the context environment
@@ -732,8 +737,7 @@ protected void initMessageSource() {
 			this.messageSource = dms;
 			beanFactory.registerSingleton(MESSAGE_SOURCE_BEAN_NAME, this.messageSource);
 			if (logger.isTraceEnabled()) {
-				logger.trace("Unable to locate MessageSource with name '" + MESSAGE_SOURCE_BEAN_NAME +
-						"': using default [" + this.messageSource + "]");
+				logger.trace("No '" + MESSAGE_SOURCE_BEAN_NAME + "' bean, using [" + this.messageSource + "]");
 			}
 		}
 	}
@@ -756,9 +760,8 @@ protected void initApplicationEventMulticaster() {
 			this.applicationEventMulticaster = new SimpleApplicationEventMulticaster(beanFactory);
 			beanFactory.registerSingleton(APPLICATION_EVENT_MULTICASTER_BEAN_NAME, this.applicationEventMulticaster);
 			if (logger.isTraceEnabled()) {
-				logger.trace("Unable to locate ApplicationEventMulticaster with name '" +
-						APPLICATION_EVENT_MULTICASTER_BEAN_NAME +
-						"': using default [" + this.applicationEventMulticaster + "]");
+				logger.trace("No '" + APPLICATION_EVENT_MULTICASTER_BEAN_NAME + "' bean, using " +
+						"[" + this.applicationEventMulticaster.getClass().getSimpleName() + "]");
 			}
 		}
 	}
@@ -783,9 +786,8 @@ protected void initLifecycleProcessor() {
 			this.lifecycleProcessor = defaultProcessor;
 			beanFactory.registerSingleton(LIFECYCLE_PROCESSOR_BEAN_NAME, this.lifecycleProcessor);
 			if (logger.isTraceEnabled()) {
-				logger.trace("Unable to locate LifecycleProcessor with name '" +
-						LIFECYCLE_PROCESSOR_BEAN_NAME +
-						"': using default [" + this.lifecycleProcessor + "]");
+				logger.trace("No '" + LIFECYCLE_PROCESSOR_BEAN_NAME + "' bean, using " +
+						"[" + this.lifecycleProcessor.getClass().getSimpleName() + "]");
 			}
 		}
 	}
@@ -1384,14 +1386,10 @@ public boolean isRunning() {
 	@Override
 	public String toString() {
 		StringBuilder sb = new StringBuilder(getDisplayName());
-		sb.append(": startup date [").append(new Date(getStartupDate()));
-		sb.append("]; ");
+		sb.append(", started on ").append(new Date(getStartupDate()));
 		ApplicationContext parent = getParent();
-		if (parent == null) {
-			sb.append("root of context hierarchy");
-		}
-		else {
-			sb.append("parent: ").append(parent.getDisplayName());
+		if (parent != null) {
+			sb.append(", parent: ").append(parent.getDisplayName());
 		}
 		return sb.toString();
 	}
diff --git a/spring-context/src/main/java/org/springframework/context/support/DelegatingMessageSource.java b/spring-context/src/main/java/org/springframework/context/support/DelegatingMessageSource.java
@@ -92,4 +92,10 @@ public String getMessage(MessageSourceResolvable resolvable, Locale locale) thro
 		}
 	}
 
+
+	@Override
+	public String toString() {
+		return this.parentMessageSource != null ? this.parentMessageSource.toString() : "Empty MessageSource";
+	}
+
 }
diff --git a/spring-web/src/main/java/org/springframework/web/context/ContextLoader.java b/spring-web/src/main/java/org/springframework/web/context/ContextLoader.java
@@ -303,7 +303,7 @@ else if (ccl != null) {
 
 			if (logger.isInfoEnabled()) {
 				long elapsedTime = System.currentTimeMillis() - startTime;
-				logger.info("Root WebApplicationContext: initialization completed in " + elapsedTime + " ms");
+				logger.info("Root WebApplicationContext initialized in " + elapsedTime + " ms");
 			}
 
 			return this.context;
diff --git a/spring-web/src/main/java/org/springframework/web/context/support/AnnotationConfigWebApplicationContext.java b/spring-web/src/main/java/org/springframework/web/context/support/AnnotationConfigWebApplicationContext.java
@@ -230,7 +230,7 @@ protected void loadBeanDefinitions(DefaultListableBeanFactory beanFactory) {
 				try {
 					Class<?> clazz = ClassUtils.forName(configLocation, getClassLoader());
 					if (logger.isTraceEnabled()) {
-						logger.trace("Successfully resolved class for [" + configLocation + "]");
+						logger.trace("Registering [" + configLocation + "]");
 					}
 					reader.register(clazz);
 				}
diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/FrameworkServlet.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/FrameworkServlet.java
@@ -516,9 +516,9 @@ public void setApplicationContext(ApplicationContext applicationContext) {
 	 */
 	@Override
 	protected final void initServletBean() throws ServletException {
-		getServletContext().log("Initializing Spring FrameworkServlet '" + getServletName() + "'");
+		getServletContext().log("Initializing Spring " + getClass().getSimpleName() + " '" + getServletName() + "'");
 		if (logger.isInfoEnabled()) {
-			logger.info("FrameworkServlet '" + getServletName() + "': initialization started");
+			logger.info("Initializing Servlet '" + getServletName() + "'");
 		}
 		long startTime = System.currentTimeMillis();
 
@@ -540,9 +540,7 @@ protected final void initServletBean() throws ServletException {
 		}
 
 		if (logger.isInfoEnabled()) {
-			long elapsedTime = System.currentTimeMillis() - startTime;
-			logger.info("FrameworkServlet '" + getServletName() + "': initialization completed in " +
-					elapsedTime + " ms");
+			logger.info("Completed initialization in " + (System.currentTimeMillis() - startTime) + " ms");
 		}
 	}
 
@@ -600,10 +598,6 @@ protected WebApplicationContext initWebApplicationContext() {
 			// Publish the context as a servlet context attribute.
 			String attrName = getServletContextAttributeName();
 			getServletContext().setAttribute(attrName, wac);
-			if (logger.isTraceEnabled()) {
-				logger.trace("Published WebApplicationContext of servlet '" + getServletName() +
-						"' as ServletContext attribute [" + attrName + "]");
-			}
 		}
 
 		return wac;
@@ -650,11 +644,6 @@ protected WebApplicationContext findWebApplicationContext() {
 	 */
 	protected WebApplicationContext createWebApplicationContext(@Nullable ApplicationContext parent) {
 		Class<?> contextClass = getContextClass();
-		if (logger.isTraceEnabled()) {
-			logger.trace("Servlet '" + getServletName() +
-					"' will create custom WebApplicationContext context of class '" +
-					contextClass.getName() + "'" + ", parent context [" + parent + "]");
-		}
 		if (!ConfigurableWebApplicationContext.class.isAssignableFrom(contextClass)) {
 			throw new ApplicationContextException(
 					"Fatal initialization error in servlet with name '" + getServletName() +
@@ -1071,19 +1060,13 @@ private void initContextHolders(HttpServletRequest request,
 		if (requestAttributes != null) {
 			RequestContextHolder.setRequestAttributes(requestAttributes, this.threadContextInheritable);
 		}
-		if (logger.isTraceEnabled()) {
-			logger.trace("Bound request context to thread: " + request);
-		}
 	}
 
 	private void resetContextHolders(HttpServletRequest request,
 			@Nullable LocaleContext prevLocaleContext, @Nullable RequestAttributes previousAttributes) {
 
 		LocaleContextHolder.setLocaleContext(prevLocaleContext, this.threadContextInheritable);
 		RequestContextHolder.setRequestAttributes(previousAttributes, this.threadContextInheritable);
-		if (logger.isTraceEnabled()) {
-			logger.trace("Cleared thread-bound request context: " + request);
-		}
 	}
 
 	private void logResult(HttpServletRequest request, HttpServletResponse response,
diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/HttpServletBean.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/HttpServletBean.java
@@ -146,9 +146,6 @@ protected ConfigurableEnvironment createEnvironment() {
 	 */
 	@Override
 	public final void init() throws ServletException {
-		if (logger.isTraceEnabled()) {
-			logger.trace("Initializing servlet '" + getServletName() + "'");
-		}
 
 		// Set bean properties from init parameters.
 		PropertyValues pvs = new ServletConfigPropertyValues(getServletConfig(), this.requiredProperties);
@@ -170,10 +167,6 @@ public final void init() throws ServletException {
 
 		// Let subclasses do whatever initialization they like.
 		initServletBean();
-
-		if (logger.isTraceEnabled()) {
-			logger.trace("Servlet '" + getServletName() + "' configured successfully");
-		}
 	}
 
 	/**

Original file line number	Diff line number	Diff line change
`@@ -585,7 +585,12 @@ protected void prepareRefresh() {`
`585`	`585`	`this.active.set(true);`
`586`	`586`
`587`	`587`	`if (logger.isDebugEnabled()) {`
`588`		`- logger.debug("Refreshing " + this);`
	`588`	`+ if (logger.isTraceEnabled()) {`
	`589`	`+ logger.trace("Refreshing " + this);`
	`590`	`+ }`
	`591`	`+ else {`
	`592`	`+ logger.debug("Refreshing " + getDisplayName());`
	`593`	`+ }`
`589`	`594`	`}`
`590`	`595`
`591`	`596`	`// Initialize any placeholder property sources in the context environment`
`@@ -732,8 +737,7 @@ protected void initMessageSource() {`
`732`	`737`	`this.messageSource = dms;`
`733`	`738`	`beanFactory.registerSingleton(MESSAGE_SOURCE_BEAN_NAME, this.messageSource);`
`734`	`739`	`if (logger.isTraceEnabled()) {`
`735`		`- logger.trace("Unable to locate MessageSource with name '" + MESSAGE_SOURCE_BEAN_NAME +`
`736`		`- "': using default [" + this.messageSource + "]");`
	`740`	`+ logger.trace("No '" + MESSAGE_SOURCE_BEAN_NAME + "' bean, using [" + this.messageSource + "]");`
`737`	`741`	`}`
`738`	`742`	`}`
`739`	`743`	`}`
`@@ -756,9 +760,8 @@ protected void initApplicationEventMulticaster() {`
`756`	`760`	`this.applicationEventMulticaster = new SimpleApplicationEventMulticaster(beanFactory);`
`757`	`761`	`beanFactory.registerSingleton(APPLICATION_EVENT_MULTICASTER_BEAN_NAME, this.applicationEventMulticaster);`
`758`	`762`	`if (logger.isTraceEnabled()) {`
`759`		`- logger.trace("Unable to locate ApplicationEventMulticaster with name '" +`
`760`		`- APPLICATION_EVENT_MULTICASTER_BEAN_NAME +`
`761`		`- "': using default [" + this.applicationEventMulticaster + "]");`
	`763`	`+ logger.trace("No '" + APPLICATION_EVENT_MULTICASTER_BEAN_NAME + "' bean, using " +`
	`764`	`+ "[" + this.applicationEventMulticaster.getClass().getSimpleName() + "]");`
`762`	`765`	`}`
`763`	`766`	`}`
`764`	`767`	`}`
`@@ -783,9 +786,8 @@ protected void initLifecycleProcessor() {`
`783`	`786`	`this.lifecycleProcessor = defaultProcessor;`
`784`	`787`	`beanFactory.registerSingleton(LIFECYCLE_PROCESSOR_BEAN_NAME, this.lifecycleProcessor);`
`785`	`788`	`if (logger.isTraceEnabled()) {`
`786`		`- logger.trace("Unable to locate LifecycleProcessor with name '" +`
`787`		`- LIFECYCLE_PROCESSOR_BEAN_NAME +`
`788`		`- "': using default [" + this.lifecycleProcessor + "]");`
	`789`	`+ logger.trace("No '" + LIFECYCLE_PROCESSOR_BEAN_NAME + "' bean, using " +`
	`790`	`+ "[" + this.lifecycleProcessor.getClass().getSimpleName() + "]");`
`789`	`791`	`}`
`790`	`792`	`}`
`791`	`793`	`}`
`@@ -1384,14 +1386,10 @@ public boolean isRunning() {`
`1384`	`1386`	`@Override`
`1385`	`1387`	`public String toString() {`
`1386`	`1388`	`StringBuilder sb = new StringBuilder(getDisplayName());`
`1387`		`- sb.append(": startup date [").append(new Date(getStartupDate()));`
`1388`		`- sb.append("]; ");`
	`1389`	`+ sb.append(", started on ").append(new Date(getStartupDate()));`
`1389`	`1390`	`ApplicationContext parent = getParent();`
`1390`		`- if (parent == null) {`
`1391`		`- sb.append("root of context hierarchy");`
`1392`		`- }`
`1393`		`- else {`
`1394`		`- sb.append("parent: ").append(parent.getDisplayName());`
	`1391`	`+ if (parent != null) {`
	`1392`	`+ sb.append(", parent: ").append(parent.getDisplayName());`
`1395`	`1393`	`}`
`1396`	`1394`	`return sb.toString();`
`1397`	`1395`	`}`
Original file line number	Diff line number	Diff line change
`@@ -92,4 +92,10 @@ public String getMessage(MessageSourceResolvable resolvable, Locale locale) thro`
`92`	`92`	`}`
`93`	`93`	`}`
`94`	`94`
	`95`	`+`
	`96`	`+ @Override`
	`97`	`+ public String toString() {`
	`98`	`+ return this.parentMessageSource != null ? this.parentMessageSource.toString() : "Empty MessageSource";`
	`99`	`+ }`
	`100`	`+`
`95`	`101`	`}`
Original file line number	Diff line number	Diff line change
`@@ -303,7 +303,7 @@ else if (ccl != null) {`
`303`	`303`
`304`	`304`	`if (logger.isInfoEnabled()) {`
`305`	`305`	`long elapsedTime = System.currentTimeMillis() - startTime;`
`306`		`- logger.info("Root WebApplicationContext: initialization completed in " + elapsedTime + " ms");`
	`306`	`+ logger.info("Root WebApplicationContext initialized in " + elapsedTime + " ms");`
`307`	`307`	`}`
`308`	`308`
`309`	`309`	`return this.context;`
Original file line number	Diff line number	Diff line change
`@@ -230,7 +230,7 @@ protected void loadBeanDefinitions(DefaultListableBeanFactory beanFactory) {`
`230`	`230`	`try {`
`231`	`231`	`Class<?> clazz = ClassUtils.forName(configLocation, getClassLoader());`
`232`	`232`	`if (logger.isTraceEnabled()) {`
`233`		`- logger.trace("Successfully resolved class for [" + configLocation + "]");`
	`233`	`+ logger.trace("Registering [" + configLocation + "]");`
`234`	`234`	`}`
`235`	`235`	`reader.register(clazz);`
`236`	`236`	`}`