Correlated WebFlux server log messages

Issue: SPR-16966
This commit is contained in:
Rossen Stoyanchev
2018-07-03 15:54:19 -04:00
parent 010ba33d03
commit fd90b73748
27 changed files with 146 additions and 60 deletions

View File

@@ -429,5 +429,10 @@ class DefaultServerRequestBuilder implements ServerRequest.Builder {
public void addUrlTransformer(Function<String, String> transformer) {
this.delegate.addUrlTransformer(transformer);
}
@Override
public String getLogPrefix() {
return this.delegate.getLogPrefix();
}
}
}

View File

@@ -809,7 +809,8 @@ public abstract class RouterFunctions {
public Mono<HandlerFunction<T>> route(ServerRequest request) {
if (this.predicate.test(request)) {
if (logger.isTraceEnabled()) {
logger.trace(String.format("Matched %s", this.predicate));
String logPrefix = request.exchange().getLogPrefix();
logger.trace(logPrefix + String.format("Matched %s", this.predicate));
}
return Mono.just(this.handlerFunction);
}
@@ -844,7 +845,8 @@ public abstract class RouterFunctions {
return this.predicate.nest(serverRequest)
.map(nestedRequest -> {
if (logger.isTraceEnabled()) {
logger.trace(String.format("Matched nested %s", this.predicate));
String logPrefix = serverRequest.exchange().getLogPrefix();
logger.trace(logPrefix + String.format("Matched nested %s", this.predicate));
}
return this.routerFunction.route(nestedRequest)
.doOnNext(match -> {

View File

@@ -160,7 +160,7 @@ public abstract class AbstractHandlerMapping extends ApplicationObjectSupport
public Mono<Object> getHandler(ServerWebExchange exchange) {
return getHandlerInternal(exchange).map(handler -> {
if (logger.isDebugEnabled()) {
logger.debug("Mapped to " + handler);
logger.debug(exchange.getLogPrefix() + "Mapped to " + handler);
}
if (CorsUtils.isCorsRequest(exchange.getRequest())) {
CorsConfiguration configA = this.globalCorsConfigSource.getCorsConfiguration(exchange);

View File

@@ -119,7 +119,7 @@ public abstract class AbstractUrlHandlerMapping extends AbstractHandlerMapping {
if (matches.size() > 1) {
matches.sort(PathPattern.SPECIFICITY_COMPARATOR);
if (logger.isTraceEnabled()) {
logger.debug("Matching patterns " + matches);
logger.debug(exchange.getLogPrefix() + "Matching patterns " + matches);
}
}

View File

@@ -127,7 +127,8 @@ public class AppCacheManifestTransformer extends ResourceTransformerSupport {
if (!content.startsWith(MANIFEST_HEADER)) {
if (logger.isTraceEnabled()) {
logger.trace("Skipping " + resource + ": Manifest does not start with 'CACHE MANIFEST'");
logger.trace(exchange.getLogPrefix() +
"Skipping " + resource + ": Manifest does not start with 'CACHE MANIFEST'");
}
return Mono.just(resource);
}

View File

@@ -112,7 +112,8 @@ public class CachingResourceResolver extends AbstractResourceResolver {
Resource cachedResource = this.cache.get(key, Resource.class);
if (cachedResource != null) {
logger.trace("Resource resolved from cache");
String logPrefix = exchange != null ? exchange.getLogPrefix() : "";
logger.trace(logPrefix + "Resource resolved from cache");
return Mono.just(cachedResource);
}

View File

@@ -69,7 +69,7 @@ public class CachingResourceTransformer implements ResourceTransformer {
Resource cachedResource = this.cache.get(resource, Resource.class);
if (cachedResource != null) {
logger.trace("Resource resolved from cache");
logger.trace(exchange.getLogPrefix() + "Resource resolved from cache");
return Mono.just(cachedResource);
}

View File

@@ -153,7 +153,8 @@ public class EncodedResourceResolver extends AbstractResourceResolver {
}
}
catch (IOException ex) {
logger.trace("No " + coding + " resource for [" + resource.getFilename() + "]", ex);
logger.trace(exchange.getLogPrefix() +
"No " + coding + " resource for [" + resource.getFilename() + "]", ex);
}
}
}

View File

@@ -59,7 +59,8 @@ public class GzipResourceResolver extends AbstractResourceResolver {
}
}
catch (IOException ex) {
logger.trace("No gzip resource for [" + resource.getFilename() + "]", ex);
String logPrefix = exchange != null ? exchange.getLogPrefix() : "";
logger.trace(logPrefix + "No gzip resource for [" + resource.getFilename() + "]", ex);
}
}
return resource;

View File

@@ -124,7 +124,7 @@ public class ResourceUrlProvider implements ApplicationListener<ContextRefreshed
String query = uriString.substring(queryIndex);
PathContainer parsedLookupPath = PathContainer.parsePath(lookupPath);
return resolveResourceUrl(parsedLookupPath).map(resolvedPath ->
return resolveResourceUrl(exchange, parsedLookupPath).map(resolvedPath ->
request.getPath().contextPath().value() + resolvedPath + query);
}
@@ -141,7 +141,7 @@ public class ResourceUrlProvider implements ApplicationListener<ContextRefreshed
return suffixIndex;
}
private Mono<String> resolveResourceUrl(PathContainer lookupPath) {
private Mono<String> resolveResourceUrl(ServerWebExchange exchange, PathContainer lookupPath) {
return this.handlerMap.entrySet().stream()
.filter(entry -> entry.getKey().matches(lookupPath))
.sorted((entry1, entry2) ->
@@ -159,7 +159,7 @@ public class ResourceUrlProvider implements ApplicationListener<ContextRefreshed
})
.orElseGet(() ->{
if (logger.isTraceEnabled()) {
logger.trace("No match for \"" + lookupPath + "\"");
logger.trace(exchange.getLogPrefix() + "No match for \"" + lookupPath + "\"");
}
return Mono.empty();
});

View File

@@ -23,8 +23,11 @@ import java.time.Instant;
import java.util.ArrayList;
import java.util.Collections;
import java.util.EnumSet;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.function.Supplier;
import java.util.stream.Collectors;
import org.apache.commons.logging.Log;
@@ -33,6 +36,7 @@ import reactor.core.publisher.Mono;
import org.springframework.beans.factory.InitializingBean;
import org.springframework.core.ResolvableType;
import org.springframework.core.codec.Encoder;
import org.springframework.core.io.Resource;
import org.springframework.core.io.ResourceLoader;
import org.springframework.http.CacheControl;
@@ -322,7 +326,7 @@ public class ResourceWebHandler implements WebHandler, InitializingBean {
public Mono<Void> handle(ServerWebExchange exchange) {
return getResource(exchange)
.switchIfEmpty(Mono.defer(() -> {
logger.debug("Resource not found");
logger.debug(exchange.getLogPrefix() + "Resource not found");
return Mono.error(NOT_FOUND_EXCEPTION);
}))
.flatMap(resource -> {
@@ -341,7 +345,7 @@ public class ResourceWebHandler implements WebHandler, InitializingBean {
// Header phase
if (exchange.checkNotModified(Instant.ofEpochMilli(resource.lastModified()))) {
logger.trace("Resource not modified");
logger.trace(exchange.getLogPrefix() + "Resource not modified");
return Mono.empty();
}

View File

@@ -185,8 +185,9 @@ public class VersionResourceResolver extends AbstractResourceResolver {
}
else {
if (logger.isTraceEnabled()) {
logger.trace("Found resource for \"" + requestPath + "\", but version [" +
candidate + "] does not match");
String logPrefix = exchange != null ? exchange.getLogPrefix() : "";
logger.trace(logPrefix + "Found resource for \"" + requestPath +
"\", but version [" + candidate + "] does not match");
}
return false;
}

View File

@@ -123,7 +123,7 @@ public abstract class HandlerResultHandlerSupport implements Ordered {
MediaType contentType = exchange.getResponse().getHeaders().getContentType();
if (contentType != null && contentType.isConcrete()) {
if (logger.isDebugEnabled()) {
logger.debug("Found 'Content-Type:" + contentType + "' in response");
logger.debug(exchange.getLogPrefix() + "Found 'Content-Type:" + contentType + "' in response");
}
return contentType;
}
@@ -146,21 +146,22 @@ public abstract class HandlerResultHandlerSupport implements Ordered {
for (MediaType mediaType : result) {
if (mediaType.isConcrete()) {
if (logger.isDebugEnabled()) {
logger.debug("Using '" + mediaType + "' given " + acceptableTypes);
logger.debug(exchange.getLogPrefix() + "Using '" + mediaType + "' given " + acceptableTypes);
}
return mediaType;
}
else if (mediaType.equals(MediaType.ALL) || mediaType.equals(MEDIA_TYPE_APPLICATION_ALL)) {
mediaType = MediaType.APPLICATION_OCTET_STREAM;
if (logger.isDebugEnabled()) {
logger.debug("Using '" + mediaType + "' given " + acceptableTypes);
logger.debug(exchange.getLogPrefix() + "Using '" + mediaType + "' given " + acceptableTypes);
}
return mediaType;
}
}
if (logger.isDebugEnabled()) {
logger.debug("No match for " + acceptableTypes + ", supported: " + producibleTypes);
logger.debug(exchange.getLogPrefix() +
"No match for " + acceptableTypes + ", supported: " + producibleTypes);
}
return null;

View File

@@ -305,7 +305,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 mappings: " + matches);
logger.trace(exchange.getLogPrefix() + matches.size() + " matching mappings: " + matches);
}
if (CorsUtils.isPreFlightRequest(exchange.getRequest())) {
return PREFLIGHT_AMBIGUOUS_MATCH;

View File

@@ -182,7 +182,7 @@ public class InvocableHandlerMethod extends HandlerMethod {
return findProvidedArgument(param, providedArgs)
.map(Mono::just)
.orElseGet(() -> {
HandlerMethodArgumentResolver resolver = findResolver(param);
HandlerMethodArgumentResolver resolver = findResolver(exchange, param);
return resolveArg(resolver, param, bindingContext, exchange);
});
@@ -207,7 +207,7 @@ public class InvocableHandlerMethod extends HandlerMethod {
.findFirst();
}
private HandlerMethodArgumentResolver findResolver(MethodParameter param) {
private HandlerMethodArgumentResolver findResolver(ServerWebExchange exchange, MethodParameter param) {
return this.resolvers.stream()
.filter(r -> r.supportsParameter(param))
.findFirst().orElseThrow(() ->
@@ -220,20 +220,22 @@ public class InvocableHandlerMethod extends HandlerMethod {
try {
return resolver.resolveArgument(parameter, bindingContext, exchange)
.defaultIfEmpty(NO_ARG_VALUE)
.doOnError(cause -> logArgumentErrorIfNecessary(parameter, cause));
.doOnError(cause -> logArgumentErrorIfNecessary(exchange, parameter, cause));
}
catch (Exception ex) {
logArgumentErrorIfNecessary(parameter, ex);
logArgumentErrorIfNecessary(exchange, parameter, ex);
return Mono.error(ex);
}
}
private void logArgumentErrorIfNecessary(MethodParameter parameter, Throwable cause) {
private void logArgumentErrorIfNecessary(
ServerWebExchange exchange, MethodParameter parameter, Throwable cause) {
// Leave stack trace for later, if error is not handled..
String message = cause.getMessage();
if (!message.contains(parameter.getExecutable().toGenericString())) {
if (logger.isDebugEnabled()) {
logger.debug(formatArgumentError(parameter, message));
logger.debug(exchange.getLogPrefix() + formatArgumentError(parameter, message));
}
}
}

View File

@@ -34,6 +34,7 @@ import org.springframework.core.ReactiveAdapterRegistry;
import org.springframework.core.ResolvableType;
import org.springframework.core.annotation.AnnotationUtils;
import org.springframework.core.codec.DecodingException;
import org.springframework.core.codec.Encoder;
import org.springframework.core.io.buffer.DataBuffer;
import org.springframework.http.HttpMethod;
import org.springframework.http.MediaType;
@@ -153,8 +154,9 @@ public abstract class AbstractMessageReaderArgumentResolver extends HandlerMetho
MediaType mediaType = (contentType != null ? contentType : MediaType.APPLICATION_OCTET_STREAM);
if (logger.isDebugEnabled()) {
logger.debug(contentType != null ? "Content-Type:" + contentType :
"No Content-Type, using " + MediaType.APPLICATION_OCTET_STREAM);
logger.debug(exchange.getLogPrefix() + (contentType != null ?
"Content-Type:" + contentType :
"No Content-Type, using " + MediaType.APPLICATION_OCTET_STREAM));
}
for (HttpMessageReader<?> reader : getMessageReaders()) {
@@ -162,7 +164,7 @@ public abstract class AbstractMessageReaderArgumentResolver extends HandlerMetho
Map<String, Object> readHints = Collections.emptyMap();
if (adapter != null && adapter.isMultiValue()) {
if (logger.isDebugEnabled()) {
logger.debug("0..N [" + elementType + "]");
logger.debug(exchange.getLogPrefix() + "0..N [" + elementType + "]");
}
Flux<?> flux = reader.read(actualType, elementType, request, response, readHints);
flux = flux.onErrorResume(ex -> Flux.error(handleReadError(bodyParam, ex)));
@@ -179,7 +181,7 @@ public abstract class AbstractMessageReaderArgumentResolver extends HandlerMetho
else {
// Single-value (with or without reactive type wrapper)
if (logger.isDebugEnabled()) {
logger.debug("0..1 [" + elementType + "]");
logger.debug(exchange.getLogPrefix() + "0..1 [" + elementType + "]");
}
Mono<?> mono = reader.readMono(actualType, elementType, request, response, readHints);
mono = mono.onErrorResume(ex -> Mono.error(handleReadError(bodyParam, ex)));

View File

@@ -18,6 +18,7 @@ package org.springframework.web.reactive.result.method.annotation;
import java.util.Collections;
import java.util.List;
import java.util.Map;
import java.util.stream.Collectors;
import org.reactivestreams.Publisher;
@@ -27,6 +28,7 @@ import org.springframework.core.MethodParameter;
import org.springframework.core.ReactiveAdapter;
import org.springframework.core.ReactiveAdapterRegistry;
import org.springframework.core.ResolvableType;
import org.springframework.core.codec.Encoder;
import org.springframework.http.MediaType;
import org.springframework.http.codec.HttpMessageWriter;
import org.springframework.http.server.reactive.ServerHttpRequest;
@@ -140,8 +142,10 @@ public abstract class AbstractMessageWriterResultHandler extends HandlerResultHa
ServerHttpResponse response = exchange.getResponse();
MediaType bestMediaType = selectMediaType(exchange, () -> getMediaTypesFor(elementType));
if (bestMediaType != null) {
String logPrefix = exchange.getLogPrefix();
if (logger.isDebugEnabled()) {
logger.debug((publisher instanceof Mono ? "0..1" : "0..N") + " [" + elementType + "]");
logger.debug(logPrefix +
(publisher instanceof Mono ? "0..1" : "0..N") + " [" + elementType + "]");
}
for (HttpMessageWriter<?> writer : getMessageWriters()) {
if (writer.canWrite(elementType, bestMediaType)) {

View File

@@ -214,7 +214,7 @@ public class RequestMappingHandlerAdapter implements HandlerAdapter, Application
if (invocable != null) {
try {
if (logger.isDebugEnabled()) {
logger.debug("Using @ExceptionHandler " + invocable);
logger.debug(exchange.getLogPrefix() + "Using @ExceptionHandler " + invocable);
}
bindingContext.getModel().asMap().clear();
Throwable cause = exception.getCause();
@@ -227,7 +227,7 @@ public class RequestMappingHandlerAdapter implements HandlerAdapter, Application
}
catch (Throwable invocationEx) {
if (logger.isWarnEnabled()) {
logger.warn("Failure in @ExceptionHandler " + invocable, invocationEx);
logger.warn(exchange.getLogPrefix() + "Failure in @ExceptionHandler " + invocable, invocationEx);
}
}
}

View File

@@ -189,7 +189,7 @@ public abstract class AbstractView implements View, BeanNameAware, ApplicationCo
ServerWebExchange exchange) {
if (logger.isDebugEnabled()) {
logger.debug("View " + formatViewName() +
logger.debug(exchange.getLogPrefix() + "View " + formatViewName() +
", model " + (model != null ? model : Collections.emptyMap()));
}

View File

@@ -188,7 +188,7 @@ public class FreeMarkerView extends AbstractUrlBasedView {
SimpleHash freeMarkerModel = getTemplateModel(renderAttributes, exchange);
if (logger.isDebugEnabled()) {
logger.debug("Rendering [" + getUrl() + "]");
logger.debug(exchange.getLogPrefix() + "Rendering [" + getUrl() + "]");
}
Locale locale = LocaleContextHolder.getLocale(exchange.getLocaleContext());

View File

@@ -214,17 +214,17 @@ public class HandshakeWebSocketService implements WebSocketService, Lifecycle {
}
if (!"WebSocket".equalsIgnoreCase(headers.getUpgrade())) {
return handleBadRequest("Invalid 'Upgrade' header: " + headers);
return handleBadRequest(exchange, "Invalid 'Upgrade' header: " + headers);
}
List<String> connectionValue = headers.getConnection();
if (!connectionValue.contains("Upgrade") && !connectionValue.contains("upgrade")) {
return handleBadRequest("Invalid 'Connection' header: " + headers);
return handleBadRequest(exchange, "Invalid 'Connection' header: " + headers);
}
String key = headers.getFirst(SEC_WEBSOCKET_KEY);
if (key == null) {
return handleBadRequest("Missing \"Sec-WebSocket-Key\" header");
return handleBadRequest(exchange, "Missing \"Sec-WebSocket-Key\" header");
}
String protocol = selectProtocol(headers, handler);
@@ -235,9 +235,9 @@ public class HandshakeWebSocketService implements WebSocketService, Lifecycle {
);
}
private Mono<Void> handleBadRequest(String reason) {
private Mono<Void> handleBadRequest(ServerWebExchange exchange, String reason) {
if (logger.isDebugEnabled()) {
logger.debug(reason);
logger.debug(exchange.getLogPrefix() + reason);
}
return Mono.error(new ServerWebInputException(reason));
}