From 7ccd2b024d88cdd8e503f77f26c32581625ca31f Mon Sep 17 00:00:00 2001 From: Rossen Stoyanchev Date: Mon, 25 Jun 2018 13:38:52 -0300 Subject: [PATCH] Refine logging for async requests Issue: SPR-16898 --- .../client/HttpMessageConverterExtractor.java | 6 +++-- .../request/async/WebAsyncManager.java | 5 ++-- .../commons/CommonsFileUploadSupport.java | 4 +-- .../commons/CommonsMultipartFile.java | 2 +- .../server/adapter/HttpWebHandlerAdapter.java | 8 +++--- .../function/client/ExchangeFunctions.java | 2 +- .../server/support/RouterFunctionMapping.java | 2 +- .../resource/PathResourceResolver.java | 2 +- .../web/servlet/DispatcherServlet.java | 8 +++--- .../web/servlet/FrameworkServlet.java | 27 +++++++++++++++---- .../handler/AbstractHandlerMapping.java | 3 ++- .../annotation/ReactiveTypeHandler.java | 19 ++++++------- ...ResponseBodyEmitterReturnValueHandler.java | 6 ----- .../resource/PathResourceResolver.java | 2 +- 14 files changed, 54 insertions(+), 42 deletions(-) diff --git a/spring-web/src/main/java/org/springframework/web/client/HttpMessageConverterExtractor.java b/spring-web/src/main/java/org/springframework/web/client/HttpMessageConverterExtractor.java index eded3e3b0e..b1173af19d 100644 --- a/spring-web/src/main/java/org/springframework/web/client/HttpMessageConverterExtractor.java +++ b/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 implements ResponseExtractor { (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 implements ResponseExtractor { 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); } diff --git a/spring-web/src/main/java/org/springframework/web/context/request/async/WebAsyncManager.java b/spring-web/src/main/java/org/springframework/web/context/request/async/WebAsyncManager.java index 9f4af63486..4527228667 100644 --- a/spring-web/src/main/java/org/springframework/web/context/request/async/WebAsyncManager.java +++ b/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(); } diff --git a/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsFileUploadSupport.java b/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsFileUploadSupport.java index 4c4bd2de49..8637a86e02 100644 --- a/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsFileUploadSupport.java +++ b/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()) { diff --git a/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsMultipartFile.java b/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsMultipartFile.java index 9a807ff89f..727cc1056f 100644 --- a/spring-web/src/main/java/org/springframework/web/multipart/commons/CommonsMultipartFile.java +++ b/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"); diff --git a/spring-web/src/main/java/org/springframework/web/server/adapter/HttpWebHandlerAdapter.java b/spring-web/src/main/java/org/springframework/web/server/adapter/HttpWebHandlerAdapter.java index 0e9fea8c5d..462959983d 100644 --- a/spring-web/src/main/java/org/springframework/web/server/adapter/HttpWebHandlerAdapter.java +++ b/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"); diff --git a/spring-webflux/src/main/java/org/springframework/web/reactive/function/client/ExchangeFunctions.java b/spring-webflux/src/main/java/org/springframework/web/reactive/function/client/ExchangeFunctions.java index 9909d5d23a..856ea06f33 100644 --- a/spring-webflux/src/main/java/org/springframework/web/reactive/function/client/ExchangeFunctions.java +++ b/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); diff --git a/spring-webflux/src/main/java/org/springframework/web/reactive/function/server/support/RouterFunctionMapping.java b/spring-webflux/src/main/java/org/springframework/web/reactive/function/server/support/RouterFunctionMapping.java index 275966ba21..809abd64e7 100644 --- a/spring-webflux/src/main/java/org/springframework/web/reactive/function/server/support/RouterFunctionMapping.java +++ b/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> routerFunctions) { - if (logger.isDebugEnabled() || logger.isTraceEnabled()) { + if (logger.isDebugEnabled()) { int total = routerFunctions.size(); String message = total + " RouterFunction(s) in " + formatMappingName(); if (logger.isTraceEnabled()) { diff --git a/spring-webflux/src/main/java/org/springframework/web/reactive/resource/PathResourceResolver.java b/spring-webflux/src/main/java/org/springframework/web/reactive/resource/PathResourceResolver.java index 260783dc59..38fcceb599 100644 --- a/spring-webflux/src/main/java/org/springframework/web/reactive/resource/PathResourceResolver.java +++ b/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); diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/DispatcherServlet.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/DispatcherServlet.java index d47138d749..4b1aff8ea5 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/DispatcherServlet.java +++ b/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 = ""; 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 index 933d56b7f9..07702d37a8 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/FrameworkServlet.java +++ b/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()) { - HttpStatus status = HttpStatus.resolve(response.getStatus()); - logger.debug("Completed " + (status != null ? status : response.getStatus())); + else { + int 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)); + } } } } diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/handler/AbstractHandlerMapping.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/handler/AbstractHandlerMapping.java index efbba4d384..eba4e21e36 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/handler/AbstractHandlerMapping.java +++ b/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()); } diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ReactiveTypeHandler.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ReactiveTypeHandler.java index 081f3df6bf..7e3602615c 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ReactiveTypeHandler.java +++ b/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()) { - logger.debug("Connection timeout for " + this.emitter); + if (logger.isTraceEnabled()) { + 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()) { - logger.debug("Send error for " + this.emitter, ex); + if (logger.isTraceEnabled()) { + 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()) { - logger.debug("Publisher error for " + this.emitter, ex); + if (logger.isTraceEnabled()) { + logger.trace("Publisher for " + this.emitter + " failed: " + ex); } this.emitter.completeWithError(ex); } else { - if (logger.isDebugEnabled()) { - logger.debug("Publisher completed for " + this.emitter); + if (logger.isTraceEnabled()) { + logger.trace("Publisher for " + this.emitter + " completed"); } this.emitter.complete(); } diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ResponseBodyEmitterReturnValueHandler.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ResponseBodyEmitterReturnValueHandler.java index 7729eb504c..c7670b7d2d 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/ResponseBodyEmitterReturnValueHandler.java +++ b/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 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) converter).write(data, mediaType, this.outputMessage); diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/resource/PathResourceResolver.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/resource/PathResourceResolver.java index 69c3007e81..2d20ae5f8a 100644 --- a/spring-webmvc/src/main/java/org/springframework/web/servlet/resource/PathResourceResolver.java +++ b/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);