Refine logging for async requests

Issue: SPR-16898

spring-web/src/main/java/org/springframework/web/client/HttpMessageConverterExtractor.java

@@ -23,6 +23,7 @@ import java.util.List;
 import org.apache.commons.logging.Log;
 import org.apache.commons.logging.LogFactory;
 
+import org.springframework.core.ResolvableType;
 import org.springframework.http.MediaType;
 import org.springframework.http.client.ClientHttpResponse;
 import org.springframework.http.converter.GenericHttpMessageConverter;
@@ -94,7 +95,8 @@ public class HttpMessageConverterExtractor<T> implements ResponseExtractor<T> {
 							(GenericHttpMessageConverter<?>) messageConverter;
 					if (genericMessageConverter.canRead(this.responseType, null, contentType)) {
 						if (logger.isDebugEnabled()) {
-							logger.debug("Reading [" + this.responseType + "]");
+							ResolvableType resolvableType = ResolvableType.forType(this.responseType);
+							logger.debug("Reading to [" + resolvableType + "]");
 						}
 						return (T) genericMessageConverter.read(this.responseType, null, responseWrapper);
 					}
@@ -103,7 +105,7 @@ public class HttpMessageConverterExtractor<T> implements ResponseExtractor<T> {
 					if (messageConverter.canRead(this.responseClass, contentType)) {
 						if (logger.isDebugEnabled()) {
 							String className = this.responseClass.getName();
-							logger.debug("Reading [" + className + "] as \"" + contentType + "\"");
+							logger.debug("Reading to [" + className + "] as \"" + contentType + "\"");
 						}
 						return (T) messageConverter.read((Class) this.responseClass, responseWrapper);
 					}

spring-web/src/main/java/org/springframework/web/context/request/async/WebAsyncManager.java

@@ -345,13 +345,14 @@ public final class WebAsyncManager {
 
 		if (this.asyncWebRequest.isAsyncComplete()) {
 			if (logger.isDebugEnabled()) {
-				logger.debug("Async request already complete for " + formatRequestUri());
+				logger.debug("Async result set but request already complete: " + formatRequestUri());
 			}
 			return;
 		}
 
 		if (logger.isDebugEnabled()) {
-			logger.debug("Async result ready, dispatch to " + formatRequestUri());
+			boolean isError = result instanceof Throwable;
+			logger.debug("Async " + (isError ? "error" : "result set") + ", dispatch to " + formatRequestUri());
 		}
 		this.asyncWebRequest.dispatch();
 	}

spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsFileUploadSupport.java

@@ -281,7 +281,7 @@ public abstract class CommonsFileUploadSupport {
 				// multipart file field
 				CommonsMultipartFile file = createMultipartFile(fileItem);
 				multipartFiles.add(file.getName(), file);
-				if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+				if (logger.isDebugEnabled()) {
 					String message = "Part '" + file.getName() + "', " +
 							"size " + file.getSize() + " bytes, filename='" + file.getOriginalFilename() + "'";
 					if (logger.isTraceEnabled()) {
@@ -323,7 +323,7 @@ public abstract class CommonsFileUploadSupport {
 				if (file instanceof CommonsMultipartFile) {
 					CommonsMultipartFile cmf = (CommonsMultipartFile) file;
 					cmf.getFileItem().delete();
-					if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+					if (logger.isDebugEnabled()) {
 						String filename = cmf.getOriginalFilename();
 						String message = "Cleaning up part '" + cmf.getName() + "', filename '" + filename + "'";
 						if (logger.isTraceEnabled()) {

spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsMultipartFile.java

@@ -165,7 +165,7 @@ public class CommonsMultipartFile implements MultipartFile, Serializable {
 
 		try {
 			this.fileItem.write(dest);
-			if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+			if (logger.isDebugEnabled()) {
 				String action = "transferred";
 				if (!this.fileItem.isInMemory()) {
 					action = (isAvailable() ? "copied" : "moved");

spring-web/src/main/java/org/springframework/web/server/adapter/HttpWebHandlerAdapter.java

@@ -194,7 +194,7 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
 	 * complete initialization.
 	 */
 	public void afterPropertiesSet() {
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 			if (this.disableLoggingRequestDetails) {
 				logger.debug("Logging query, form data, multipart data, and headers is OFF.");
 			}
@@ -228,7 +228,7 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
 	}
 
 	private void logExchange(ServerWebExchange exchange) {
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 			ServerHttpRequest request = exchange.getRequest();
 			if (logger.isTraceEnabled()) {
 				String headers = this.disableLoggingRequestDetails ? "" : ", headers=" + request.getHeaders();
@@ -246,11 +246,11 @@ public class HttpWebHandlerAdapter extends WebHandlerDecorator implements HttpHa
 			String rawQuery = request.getURI().getRawQuery();
 			query = StringUtils.hasText(rawQuery) ? "?" + rawQuery : "";
 		}
-		return "HTTP " + request.getMethod() + " " + request.getPath() + query;
+		return "HTTP " + request.getMethod() + " \"" + request.getPath() + query + "\"";
 	}
 
 	private void logResponse(ServerHttpResponse response) {
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 			HttpStatus status = response.getStatusCode();
 			String message = "Completed " + (status != null ? status : "200 OK");
 

spring-webflux/src/main/java/org/springframework/web/reactive/function/client/ExchangeFunctions.java

@@ -119,7 +119,7 @@ public abstract class ExchangeFunctions {
 		}
 
 		private void logResponse(ClientHttpResponse response) {
-			if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+			if (logger.isDebugEnabled()) {
 				int code = response.getRawStatusCode();
 				HttpStatus status = HttpStatus.resolve(code);
 				String message = "Response " + (status != null ? status : code);

spring-webflux/src/main/java/org/springframework/web/reactive/function/server/support/RouterFunctionMapping.java

@@ -118,7 +118,7 @@ public class RouterFunctionMapping extends AbstractHandlerMapping implements Ini
 	}
 
 	private void logRouterFunctions(List<RouterFunction<?>> routerFunctions) {
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 			int total = routerFunctions.size();
 			String message = total + " RouterFunction(s) in " + formatMappingName();
 			if (logger.isTraceEnabled()) {

spring-webflux/src/main/java/org/springframework/web/reactive/resource/PathResourceResolver.java

@@ -124,7 +124,7 @@ public class PathResourceResolver extends AbstractResourceResolver {
 			return Mono.empty();
 		}
 		catch (IOException ex) {
-			if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+			if (logger.isDebugEnabled()) {
 				String error = "Skip location [" + location + "] due to error";
 				if (logger.isTraceEnabled()) {
 					logger.trace(error, ex);

spring-webmvc/src/main/java/org/springframework/web/servlet/DispatcherServlet.java

@@ -530,7 +530,7 @@ public class DispatcherServlet extends FrameworkServlet {
 		initViewResolvers(context);
 		initFlashMapManager(context);
 
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 			if (this.disableLoggingRequestDetails) {
 				logger.debug("Logging request parameters and headers is OFF.");
 			}
@@ -988,7 +988,7 @@ public class DispatcherServlet extends FrameworkServlet {
 	}
 
 	private void logRequest(HttpServletRequest request) {
-		if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+		if (logger.isDebugEnabled()) {
 
 			String params = "";
 			if (!this.disableLoggingRequestDetails) {
@@ -998,9 +998,9 @@ public class DispatcherServlet extends FrameworkServlet {
 			}
 
 			String dispatchType = !request.getDispatcherType().equals(DispatcherType.REQUEST) ?
-					" [" + request.getDispatcherType().name() + "]" : "";
+					"\"" + request.getDispatcherType().name() + "\" dispatch for " : "";
 
-			String message = request.getMethod() + " " + getRequestUri(request) + dispatchType + params;
+			String message = dispatchType + request.getMethod() + " \"" + getRequestUri(request) + "\"" + params;
 
 			if (logger.isTraceEnabled()) {
 				String headers = "";

spring-webmvc/src/main/java/org/springframework/web/servlet/FrameworkServlet.java

@@ -21,6 +21,7 @@ import java.security.Principal;
 import java.util.ArrayList;
 import java.util.List;
 import java.util.concurrent.Callable;
+import javax.servlet.DispatcherType;
 import javax.servlet.ServletContext;
 import javax.servlet.ServletException;
 import javax.servlet.http.HttpServletRequest;
@@ -990,16 +991,32 @@ public abstract class FrameworkServlet extends HttpServletBean implements Applic
 			}
 
 			if (logger.isDebugEnabled()) {
+				boolean isRequestDispatch = request.getDispatcherType().equals(DispatcherType.REQUEST);
+				String dispatchType = request.getDispatcherType().name();
 				if (failureCause != null) {
-					this.logger.debug("Failed to complete request: ", failureCause);
+					if (!isRequestDispatch) {
+						logger.debug("Unresolved failure from \"" + dispatchType + "\" dispatch: " + failureCause);
+					}
+					else if (logger.isTraceEnabled()) {
+						logger.trace("Failed to complete request", failureCause);
+					}
+					else {
+						logger.debug("Failed to complete request: " + failureCause);
+					}
 				}
 				else {
 					if (asyncManager.isConcurrentHandlingStarted()) {
-						logger.debug("Exiting, but response remains open for further handling");
+						logger.debug("Exiting but response remains open for further handling");
 					}
-					else if (logger.isDebugEnabled()) {
+					else {
-						HttpStatus status = HttpStatus.resolve(response.getStatus());
+						int status = response.getStatus();
-						logger.debug("Completed " + (status != null ? status : response.getStatus()));
+						if (!isRequestDispatch) {
+							logger.debug("Exiting from \"" + dispatchType + "\" dispatch (status " + status + ")");
+						}
+						else {
+							HttpStatus httpStatus = HttpStatus.resolve(status);
+							logger.debug("Completed " + (httpStatus != null ? httpStatus : status));
+						}
 					}
 				}
 			}

spring-webmvc/src/main/java/org/springframework/web/servlet/handler/AbstractHandlerMapping.java

@@ -21,6 +21,7 @@ import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
 import java.util.Map;
+import javax.servlet.DispatcherType;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
@@ -379,7 +380,7 @@ public abstract class AbstractHandlerMapping extends WebApplicationObjectSupport
 		if (logger.isTraceEnabled()) {
 			logger.trace("Mapped to " + handler);
 		}
-		else if (logger.isDebugEnabled()) {
+		else if (logger.isDebugEnabled() && !request.getDispatcherType().equals(DispatcherType.ASYNC)) {
 			logger.debug("Mapped to " + executionChain.getHandler());
 		}
 

spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ReactiveTypeHandler.java

@@ -211,12 +211,9 @@ class ReactiveTypeHandler {
 		@Override
 		public final void onSubscribe(Subscription subscription) {
 			this.subscription = subscription;
-			if (logger.isTraceEnabled()) {
-				logger.trace("Subscribed to Publisher for " + this.emitter);
-			}
 			this.emitter.onTimeout(() -> {
-				if (logger.isDebugEnabled()) {
+				if (logger.isTraceEnabled()) {
-					logger.debug("Connection timeout for " + this.emitter);
+					logger.trace("Connection timeout for " + this.emitter);
 				}
 				terminate();
 				this.emitter.complete();
@@ -284,8 +281,8 @@ class ReactiveTypeHandler {
 					this.subscription.request(1);
 				}
 				catch (final Throwable ex) {
-					if (logger.isDebugEnabled()) {
+					if (logger.isTraceEnabled()) {
-						logger.debug("Send error for " + this.emitter, ex);
+						logger.trace("Send for " + this.emitter + " failed: " + ex);
 					}
 					terminate();
 					return;
@@ -297,14 +294,14 @@ class ReactiveTypeHandler {
 				Throwable ex = this.error;
 				this.error = null;
 				if (ex != null) {
-					if (logger.isDebugEnabled()) {
+					if (logger.isTraceEnabled()) {
-						logger.debug("Publisher error for " + this.emitter, ex);
+						logger.trace("Publisher for " + this.emitter + " failed: " + ex);
 					}
 					this.emitter.completeWithError(ex);
 				}
 				else {
-					if (logger.isDebugEnabled()) {
+					if (logger.isTraceEnabled()) {
-						logger.debug("Publisher completed for " + this.emitter);
+						logger.trace("Publisher for " + this.emitter + " completed");
 					}
 					this.emitter.complete();
 				}

spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ResponseBodyEmitterReturnValueHandler.java

@@ -20,7 +20,6 @@ import java.io.IOException;
 import java.io.OutputStream;
 import java.util.List;
 import java.util.function.Consumer;
-
 import javax.servlet.ServletRequest;
 import javax.servlet.http.HttpServletResponse;
 
@@ -192,11 +191,6 @@ public class ResponseBodyEmitterReturnValueHandler implements HandlerMethodRetur
 
 		@SuppressWarnings("unchecked")
 		private <T> void sendInternal(T data, @Nullable MediaType mediaType) throws IOException {
-			if (logger.isTraceEnabled()) {
-				String format = mediaType != null ? "\"" + mediaType + "\" from " : "";
-				logger.trace("Writing " + format + "[" +
-						(data instanceof CharSequence ? "\"" + data + "\"" : data) + "]");
-			}
 			for (HttpMessageConverter<?> converter : ResponseBodyEmitterReturnValueHandler.this.messageConverters) {
 				if (converter.canWrite(data.getClass(), mediaType)) {
 					((HttpMessageConverter<T>) converter).write(data, mediaType, this.outputMessage);

spring-webmvc/src/main/java/org/springframework/web/servlet/resource/PathResourceResolver.java

@@ -157,7 +157,7 @@ public class PathResourceResolver extends AbstractResourceResolver {
 				}
 			}
 			catch (IOException ex) {
-				if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
+				if (logger.isDebugEnabled()) {
 					String error = "Skip location [" + location + "] due to error";
 					if (logger.isTraceEnabled()) {
 						logger.trace(error, ex);