Logging improvements for WebFlux

Issue: SPR-16898
This commit is contained in:
Rossen Stoyanchev
2018-06-22 22:41:30 -04:00
parent eaffcbe3be
commit 900bc8a2e3
109 changed files with 1106 additions and 671 deletions

View File

@@ -537,9 +537,9 @@ public class DispatcherServlet extends FrameworkServlet {
else {
logger.warn("\n\n" +
"!!!!!!!!!!!!!!!!!!!\n" +
"Logging of request parameters (DEBUG level) and headers (TRACE level) may log sensitive data.\n" +
"If not in development, lower the log level for \"org.springframework.web.servlet.DispatcherServlet\", or\n" +
"set the DispatcherServlet property \"disableLoggingRequestDetails\" to 'true'.\n" +
"Logging request parameters (DEBUG) and headers (TRACE) may show sensitive data.\n" +
"If not in development, use the DispatcherServlet property \"disableLoggingRequestDetails=true\",\n" +
"or lower the log level.\n" +
"!!!!!!!!!!!!!!!!!!!\n");
}
}
@@ -1278,8 +1278,7 @@ public class DispatcherServlet extends FrameworkServlet {
*/
protected void noHandlerFound(HttpServletRequest request, HttpServletResponse response) throws Exception {
if (pageNotFoundLogger.isWarnEnabled()) {
pageNotFoundLogger.warn("No mapping for " + request.getMethod() + " " +
getRequestUri(request) + " in DispatcherServlet '" + getServletName() + "'");
pageNotFoundLogger.warn("No mapping for " + request.getMethod() + " " + getRequestUri(request));
}
if (this.throwExceptionIfNoHandlerFound) {
throw new NoHandlerFoundException(request.getMethod(), getRequestUri(request),

View File

@@ -997,9 +997,9 @@ public abstract class FrameworkServlet extends HttpServletBean implements Applic
if (asyncManager.isConcurrentHandlingStarted()) {
logger.debug("Exiting, but response remains open for further handling");
}
else {
else if (logger.isDebugEnabled()) {
HttpStatus status = HttpStatus.resolve(response.getStatus());
this.logger.debug("Completed " + (status != null ? status : response.getStatus()));
logger.debug("Completed " + (status != null ? status : response.getStatus()));
}
}
}

View File

@@ -135,10 +135,12 @@ public abstract class AbstractHandlerExceptionResolver implements HandlerExcepti
prepareResponse(ex, response);
ModelAndView result = doResolveException(request, response, handler, ex);
if (result != null) {
// One-liner at debug level..
if (logger.isDebugEnabled()) {
// Print debug message, when warn logger is not enabled..
if (logger.isDebugEnabled() && (this.warnLogger == null || !this.warnLogger.isWarnEnabled())) {
logger.debug("Resolved [" + ex + "]" + (result.isEmpty() ? "" : " to " + result));
}
// warnLogger with full stack trace (requires explicit config)..
logException(ex, request);
}
@@ -202,7 +204,7 @@ public abstract class AbstractHandlerExceptionResolver implements HandlerExcepti
* @return the log message to use
*/
protected String buildLogMessage(Exception ex, HttpServletRequest request) {
return "Resolved exception caused by Handler execution: " + ex;
return "Resolved [" + ex + "]";
}
/**

View File

@@ -197,10 +197,11 @@ public abstract class AbstractHandlerMethodMapping<T> extends AbstractHandlerMap
initHandlerMethods();
if (logger.isDebugEnabled()) {
// Total includes detected mappings + explicit registrations via registerMapping..
int total = this.getHandlerMethods().size();
logger.debug("Detected " + total + " mappings in " + formatMappingName());
// Total includes detected mappings + explicit registrations via registerMapping..
int total = this.getHandlerMethods().size();
if ((logger.isTraceEnabled() && total == 0) || (logger.isDebugEnabled() && total > 0) ) {
logger.debug(total + " mappings in " + formatMappingName());
}
}
@@ -359,7 +360,7 @@ public abstract class AbstractHandlerMethodMapping<T> extends AbstractHandlerMap
Match bestMatch = matches.get(0);
if (matches.size() > 1) {
if (logger.isTraceEnabled()) {
logger.trace(matches.size() + " matching mapppings: " + matches);
logger.trace(matches.size() + " matching mappings: " + matches);
}
if (CorsUtils.isPreFlightRequest(request)) {
return PREFLIGHT_AMBIGUOUS_MATCH;

View File

@@ -363,7 +363,7 @@ public abstract class AbstractUrlHandlerMapping extends AbstractHandlerMapping i
else {
this.handlerMap.put(urlPath, resolvedHandler);
if (logger.isTraceEnabled()) {
logger.trace("Mapped URL path [" + urlPath + "] onto " + getHandlerDescription(handler));
logger.trace("Mapped [" + urlPath + "] onto " + getHandlerDescription(handler));
}
}
}

View File

@@ -114,7 +114,7 @@ public class SimpleUrlHandlerMapping extends AbstractUrlHandlerMapping {
*/
protected void registerHandlers(Map<String, Object> urlMap) throws BeansException {
if (urlMap.isEmpty()) {
logger.warn("Neither 'urlMap' nor 'mappings' set, " + formatMappingName());
logger.trace("No patterns in " + formatMappingName());
}
else {
urlMap.forEach((url, handler) -> {

View File

@@ -215,6 +215,9 @@ public abstract class AbstractMessageConverterMethodProcessor extends AbstractMe
MediaType contentType = outputMessage.getHeaders().getContentType();
if (contentType != null && contentType.isConcrete()) {
if (logger.isDebugEnabled()) {
logger.debug("Found 'Content-Type:" + contentType + "' in response");
}
mediaTypesToUse = Collections.singletonList(contentType);
}
else {
@@ -234,6 +237,9 @@ public abstract class AbstractMessageConverterMethodProcessor extends AbstractMe
}
}
}
if (logger.isDebugEnabled()) {
logger.debug("No match for " + requestedMediaTypes + ", supported: " + producibleMediaTypes);
}
if (mediaTypesToUse.isEmpty()) {
if (body != null) {
throw new HttpMediaTypeNotAcceptableException(producibleMediaTypes);
@@ -255,6 +261,10 @@ public abstract class AbstractMessageConverterMethodProcessor extends AbstractMe
}
}
if (logger.isDebugEnabled()) {
logger.debug("Using '" + selectedMediaType + "' given " + mediaTypesToUse);
}
if (selectedMediaType != null) {
selectedMediaType = selectedMediaType.removeQualityValue();
for (HttpMessageConverter<?> converter : this.messageConverters) {
@@ -267,6 +277,10 @@ public abstract class AbstractMessageConverterMethodProcessor extends AbstractMe
(Class<? extends HttpMessageConverter<?>>) converter.getClass(),
inputMessage, outputMessage);
if (body != null) {
if (logger.isDebugEnabled()) {
Object formatted = body instanceof CharSequence ? "\"" + body + "\"" : body;
logger.debug("Writing [" + formatted + "]");
}
addContentDispositionHeader(inputMessage, outputMessage);
if (genericConverter != null) {
genericConverter.write(body, declaredType, selectedMediaType, outputMessage);
@@ -274,9 +288,10 @@ public abstract class AbstractMessageConverterMethodProcessor extends AbstractMe
else {
((HttpMessageConverter) converter).write(body, selectedMediaType, outputMessage);
}
}
else {
if (logger.isDebugEnabled()) {
logger.debug("Written \"" + selectedMediaType + "\" from " +
"[" + (body instanceof CharSequence ? "\"" + body + "\"" : body) + "]");
logger.debug("Nothing to write: null body");
}
}
return;

View File

@@ -121,7 +121,7 @@ public class ServletInvocableHandlerMethod extends InvocableHandlerMethod {
}
catch (Exception ex) {
if (logger.isTraceEnabled()) {
logger.trace(formatErrorForReturnValue("Error handling return value", returnValue), ex);
logger.trace(formatErrorForReturnValue(returnValue), ex);
}
throw ex;
}
@@ -160,13 +160,10 @@ public class ServletInvocableHandlerMethod extends InvocableHandlerMethod {
return webRequest.isNotModified();
}
private String formatErrorForReturnValue(String message, @Nullable Object returnValue) {
StringBuilder sb = new StringBuilder(message);
if (returnValue != null) {
sb.append(" [type=").append(returnValue.getClass().getName()).append("]");
}
sb.append(" [value=").append(returnValue).append("]");
return getDetailedErrorMessage(sb.toString());
private String formatErrorForReturnValue(@Nullable Object returnValue) {
return "Error handling return value=[" + returnValue + "]" +
(returnValue != null ? ", type=" + returnValue.getClass().getName() : "") +
" in " + toString();
}
/**

View File

@@ -182,8 +182,8 @@ public class CssLinkResourceTransformer extends ResourceTransformerSupport {
if (content.substring(index, index + 4).equals("url(")) {
// Ignore, UrlLinkParser will take care
}
else if (logger.isWarnEnabled()) {
logger.warn("Unexpected syntax for @import link at index " + index);
else if (logger.isTraceEnabled()) {
logger.trace("Unexpected syntax for @import link at index " + index);
}
return index;
}

View File

@@ -157,7 +157,15 @@ public class PathResourceResolver extends AbstractResourceResolver {
}
}
catch (IOException ex) {
logger.trace("Failed to get resource, skipping location: " + location, ex);
if (logger.isDebugEnabled() || logger.isTraceEnabled()) {
String error = "Skip location [" + location + "] due to error";
if (logger.isTraceEnabled()) {
logger.trace(error, ex);
}
else {
logger.debug(error + ": " + ex.getMessage());
}
}
}
}
return null;
@@ -276,9 +284,7 @@ public class PathResourceResolver extends AbstractResourceResolver {
try {
String decodedPath = URLDecoder.decode(resourcePath, "UTF-8");
if (decodedPath.contains("../") || decodedPath.contains("..\\")) {
if (logger.isTraceEnabled()) {
logger.trace("Resolved resource path contains encoded \"../\" or \"..\\\": " + resourcePath);
}
logger.warn("Resolved resource path contains encoded \"../\" or \"..\\\": " + resourcePath);
return true;
}
}

View File

@@ -450,7 +450,7 @@ public class ResourceHttpRequestHandler extends WebContentGenerator
// For very general mappings (e.g. "/") we need to check 404 first
Resource resource = getResource(request);
if (resource == null) {
logger.trace("Resource not found");
logger.debug("Resource not found");
response.sendError(HttpServletResponse.SC_NOT_FOUND);
return;
}
@@ -514,15 +514,9 @@ public class ResourceHttpRequestHandler extends WebContentGenerator
path = processPath(path);
if (!StringUtils.hasText(path) || isInvalidPath(path)) {
if (logger.isTraceEnabled()) {
logger.trace("Ignoring invalid resource path [" + path + "]");
}
return null;
}
if (isInvalidEncodedPath(path)) {
if (logger.isTraceEnabled()) {
logger.trace("Ignoring invalid resource path with escape sequences [" + path + "]");
}
return null;
}
@@ -587,8 +581,7 @@ public class ResourceHttpRequestHandler extends WebContentGenerator
if (i == 0 || (i == 1 && slash)) {
return path;
}
path = (slash ? "/" + path.substring(i) : path.substring(i));
return path;
return (slash ? "/" + path.substring(i) : path.substring(i));
}
}
return (slash ? "/" : "");
@@ -637,20 +630,20 @@ public class ResourceHttpRequestHandler extends WebContentGenerator
*/
protected boolean isInvalidPath(String path) {
if (path.contains("WEB-INF") || path.contains("META-INF")) {
logger.warn("Path contains \"WEB-INF\" or \"META-INF\".");
logger.warn("Path with \"WEB-INF\" or \"META-INF\": [" + path + "]");
return true;
}
if (path.contains(":/")) {
String relativePath = (path.charAt(0) == '/' ? path.substring(1) : path);
if (ResourceUtils.isUrl(relativePath) || relativePath.startsWith("url:")) {
logger.warn("Path represents URL or has \"url:\" prefix.");
logger.warn("Path represents URL or has \"url:\" prefix: [" + path + "]");
return true;
}
}
if (path.contains("..")) {
path = StringUtils.cleanPath(path);
if (path.contains("../")) {
logger.warn("Path contains \"../\" after call to StringUtils#cleanPath.");
logger.warn("Invalid Path contains \"../\" after call to StringUtils#cleanPath.");
return true;
}
}

View File

@@ -497,7 +497,8 @@ public abstract class AbstractView extends WebApplicationObjectSupport implement
}
protected String formatViewName() {
return (getBeanName() != null ? "name '" + getBeanName() + "'" : "[unnamed]");
return (getBeanName() != null ?
"name '" + getBeanName() + "'" : "[" + getClass().getSimpleName() + "]");
}
}