Improve DEBUG/TRACE logging for Spring MVC

Issue: SPR-16898
This commit is contained in:
Rossen Stoyanchev
2018-06-18 17:48:55 -04:00
parent 003d643adc
commit 28a5c3009e
69 changed files with 585 additions and 602 deletions

View File

@@ -304,4 +304,8 @@ public class CacheControl {
builder.append(value);
}
@Override
public String toString() {
return "CacheControl [" + getHeaderValue() + "]";
}
}

View File

@@ -504,7 +504,7 @@ public enum HttpStatus {
*/
@Override
public String toString() {
return Integer.toString(this.value);
return Integer.toString(this.value) + " " + name();
}

View File

@@ -138,9 +138,6 @@ public abstract class AbstractMappingContentNegotiationStrategy extends MappingM
* {@link #lookupMediaType}.
*/
protected void handleMatch(String key, MediaType mediaType) {
if (logger.isTraceEnabled()) {
logger.trace("Requested MediaType='" + mediaType + "' based on key='" + key + "'.");
}
}
/**

View File

@@ -69,9 +69,6 @@ public class FixedContentNegotiationStrategy implements ContentNegotiationStrate
@Override
public List<MediaType> resolveMediaTypes(NativeWebRequest request) {
if (logger.isDebugEnabled()) {
logger.debug("Requested media types: " + this.contentTypes);
}
return this.contentTypes;
}

View File

@@ -87,7 +87,6 @@ public class PathExtensionContentNegotiationStrategy extends AbstractMappingCont
protected String getMediaTypeKey(NativeWebRequest webRequest) {
HttpServletRequest request = webRequest.getNativeRequest(HttpServletRequest.class);
if (request == null) {
logger.warn("An HttpServletRequest is required to determine the media type key");
return null;
}
String path = this.urlPathHelper.getLookupPathForRequest(request);

View File

@@ -61,10 +61,13 @@ public class MethodArgumentNotValidException extends Exception {
@Override
public String getMessage() {
StringBuilder sb = new StringBuilder("Validation failed for argument at index ")
.append(this.parameter.getParameterIndex()).append(" in method: ")
.append(this.parameter.getExecutable().toGenericString())
.append(", with ").append(this.bindingResult.getErrorCount()).append(" error(s): ");
StringBuilder sb = new StringBuilder("Validation failed for argument [")
.append(this.parameter.getParameterIndex()).append("] in ")
.append(this.parameter.getExecutable().toGenericString());
if (this.bindingResult.getErrorCount() > 1) {
sb.append(" with ").append(this.bindingResult.getErrorCount()).append(" errors");
}
sb.append(": ");
for (ObjectError error : this.bindingResult.getAllErrors()) {
sb.append("[").append(error).append("] ");
}

View File

@@ -72,13 +72,13 @@ class CallableInterceptorChain {
try {
this.interceptors.get(i).postProcess(request, task, concurrentResult);
}
catch (Throwable t) {
catch (Throwable ex) {
// Save the first exception but invoke all interceptors
if (exceptionResult != null) {
logger.error("postProcess error", t);
logger.warn("Unhandled error from interceptor postProcess method", ex);
}
else {
exceptionResult = t;
exceptionResult = ex;
}
}
}
@@ -140,8 +140,8 @@ class CallableInterceptorChain {
try {
this.interceptors.get(i).afterCompletion(request, task);
}
catch (Throwable t) {
logger.error("afterCompletion error", t);
catch (Throwable ex) {
logger.error("Unhandled error from interceptor afterCompletion method", ex);
}
}
}

View File

@@ -65,8 +65,8 @@ class DeferredResultInterceptorChain {
this.interceptors.get(i).postProcess(request, deferredResult, concurrentResult);
}
}
catch (Throwable t) {
return t;
catch (Throwable ex) {
return ex;
}
return concurrentResult;
}
@@ -105,8 +105,8 @@ class DeferredResultInterceptorChain {
try {
this.interceptors.get(i).afterCompletion(request, deferredResult);
}
catch (Throwable t) {
logger.error("afterCompletion error", t);
catch (Throwable ex) {
logger.error("Unhandled error from interceptor afterCompletion method", ex);
}
}
}

View File

@@ -290,7 +290,7 @@ public final class WebAsyncManager {
final CallableInterceptorChain interceptorChain = new CallableInterceptorChain(interceptors);
this.asyncWebRequest.addTimeoutHandler(() -> {
logger.debug("Processing timeout");
logger.debug("Async request timeout for " + formatRequestUri());
Object result = interceptorChain.triggerAfterTimeout(this.asyncWebRequest, callable);
if (result != CallableProcessingInterceptor.RESULT_NONE) {
setConcurrentResultAndDispatch(result);
@@ -298,7 +298,7 @@ public final class WebAsyncManager {
});
this.asyncWebRequest.addErrorHandler(ex -> {
logger.debug("Processing error");
logger.debug("Async request error for " + formatRequestUri() + ": " + ex);
Object result = interceptorChain.triggerAfterError(this.asyncWebRequest, callable, ex);
result = (result != CallableProcessingInterceptor.RESULT_NONE ? result : ex);
setConcurrentResultAndDispatch(result);
@@ -333,6 +333,11 @@ public final class WebAsyncManager {
}
}
private String formatRequestUri() {
HttpServletRequest request = this.asyncWebRequest.getNativeRequest(HttpServletRequest.class);
return request != null ? urlPathHelper.getRequestUri(request) : "servlet container";
}
private void setConcurrentResultAndDispatch(Object result) {
synchronized (WebAsyncManager.this) {
if (this.concurrentResult != RESULT_NONE) {
@@ -347,8 +352,7 @@ public final class WebAsyncManager {
}
if (logger.isDebugEnabled()) {
logger.debug("Concurrent result value [" + this.concurrentResult +
"] - dispatching request to resume processing");
logger.debug("Async result ready, dispatch to " + formatRequestUri());
}
this.asyncWebRequest.dispatch();
}
@@ -432,11 +436,7 @@ public final class WebAsyncManager {
this.asyncWebRequest.startAsync();
if (logger.isDebugEnabled()) {
HttpServletRequest request = this.asyncWebRequest.getNativeRequest(HttpServletRequest.class);
if (request != null) {
String requestUri = urlPathHelper.getRequestUri(request);
logger.debug("Concurrent handling starting for " + request.getMethod() + " [" + requestUri + "]");
}
logger.debug("Started async request");
}
}

View File

@@ -68,13 +68,13 @@ public class DefaultCorsProcessor implements CorsProcessor {
ServletServerHttpResponse serverResponse = new ServletServerHttpResponse(response);
if (responseHasCors(serverResponse)) {
logger.debug("Skip CORS processing: response already contains \"Access-Control-Allow-Origin\" header");
logger.trace("Skip CORS processing: response already contains \"Access-Control-Allow-Origin\" header");
return true;
}
ServletServerHttpRequest serverRequest = new ServletServerHttpRequest(request);
if (WebUtils.isSameOrigin(serverRequest)) {
logger.debug("Skip CORS processing: request is from same origin");
logger.trace("Skip CORS processing: request is from same origin");
return true;
}

View File

@@ -26,6 +26,7 @@ import org.springframework.core.ParameterNameDiscoverer;
import org.springframework.lang.Nullable;
import org.springframework.util.ClassUtils;
import org.springframework.util.ReflectionUtils;
import org.springframework.util.StringUtils;
import org.springframework.web.bind.WebDataBinder;
import org.springframework.web.bind.support.SessionStatus;
import org.springframework.web.bind.support.WebDataBinderFactory;
@@ -163,24 +164,26 @@ public class InvocableHandlerMethod extends HandlerMethod {
continue;
}
catch (Exception ex) {
if (logger.isDebugEnabled()) {
logger.debug(getArgumentResolutionErrorMessage("Failed to resolve", i), ex);
// Leave stack trace for later, e.g. AbstractHandlerExceptionResolver
String message = ex.getMessage();
if (!message.contains(parameter.getExecutable().toGenericString())) {
if (logger.isDebugEnabled()) {
logger.debug(formatArgumentError(parameter, message));
}
}
throw ex;
}
}
if (args[i] == null) {
throw new IllegalStateException("Could not resolve method parameter at index " +
parameter.getParameterIndex() + " in " + parameter.getExecutable().toGenericString() +
": " + getArgumentResolutionErrorMessage("No suitable resolver for", i));
throw new IllegalStateException(formatArgumentError(parameter, "No suitable resolver"));
}
}
return args;
}
private String getArgumentResolutionErrorMessage(String text, int index) {
Class<?> paramType = getMethodParameters()[index].getParameterType();
return text + " argument " + index + " of type '" + paramType.getName() + "'";
private static String formatArgumentError(MethodParameter param, String message) {
return "Could not resolve parameter [" + param.getParameterIndex() + "] in " +
param.getExecutable().toGenericString() + (StringUtils.hasText(message) ? ": " + message : "");
}
/**

View File

@@ -281,10 +281,15 @@ public abstract class CommonsFileUploadSupport {
// multipart file field
CommonsMultipartFile file = createMultipartFile(fileItem);
multipartFiles.add(file.getName(), file);
if (logger.isDebugEnabled()) {
logger.debug("Found multipart file [" + file.getName() + "] of size " + file.getSize() +
" bytes with original filename [" + file.getOriginalFilename() + "], stored " +
file.getStorageDescription());
if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
String message = "Part '" + file.getName() + "', " +
"size " + file.getSize() + " bytes, filename='" + file.getOriginalFilename() + "'";
if (logger.isTraceEnabled()) {
logger.trace(message + ", storage=" + file.getStorageDescription());
}
else {
logger.debug(message);
}
}
}
}
@@ -318,9 +323,15 @@ public abstract class CommonsFileUploadSupport {
if (file instanceof CommonsMultipartFile) {
CommonsMultipartFile cmf = (CommonsMultipartFile) file;
cmf.getFileItem().delete();
if (logger.isDebugEnabled()) {
logger.debug("Cleaning up multipart file [" + cmf.getName() + "] with original filename [" +
cmf.getOriginalFilename() + "], stored " + cmf.getStorageDescription());
if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
String filename = cmf.getOriginalFilename();
String message = "Cleaning up part '" + cmf.getName() + "', filename '" + filename + "'";
if (logger.isTraceEnabled()) {
logger.trace(message + ", stored " + cmf.getStorageDescription());
}
else {
logger.debug(message);
}
}
}
}

View File

@@ -165,14 +165,19 @@ public class CommonsMultipartFile implements MultipartFile, Serializable {
try {
this.fileItem.write(dest);
if (logger.isDebugEnabled()) {
if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
String action = "transferred";
if (!this.fileItem.isInMemory()) {
action = (isAvailable() ? "copied" : "moved");
}
logger.debug("Multipart file '" + getName() + "' with original filename [" +
getOriginalFilename() + "], stored " + getStorageDescription() + ": " +
action + " to [" + dest.getAbsolutePath() + "]");
String message = "Part '" + getName() + "', filename '" + getOriginalFilename() + "'";
if (logger.isTraceEnabled()) {
logger.trace(message + ", stored " + getStorageDescription() + ": " + action +
" to [" + dest.getAbsolutePath() + "]");
}
else {
logger.debug(message + ": " + action + " to [" + dest.getAbsolutePath() + "]");
}
}
}
catch (FileUploadException ex) {

View File

@@ -106,16 +106,15 @@ public class MultipartFilter extends OncePerRequestFilter {
HttpServletRequest processedRequest = request;
if (multipartResolver.isMultipart(processedRequest)) {
if (logger.isDebugEnabled()) {
logger.debug("Resolving multipart request [" + processedRequest.getRequestURI() +
"] with MultipartFilter");
if (logger.isTraceEnabled()) {
logger.trace("Resolving multipart request");
}
processedRequest = multipartResolver.resolveMultipart(processedRequest);
}
else {
// A regular request...
if (logger.isDebugEnabled()) {
logger.debug("Request [" + processedRequest.getRequestURI() + "] is not a multipart request");
if (logger.isTraceEnabled()) {
logger.trace("Not a multipart request");
}
}