Improved logging in functional web framework

This commit improves predicate and route logging in the functional web
framework.

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

@@ -127,6 +127,11 @@ class DefaultServerRequest implements ServerRequest {
 		return this.exchange.getAttribute(name);
 	}
 
+	@Override
+	public Map<String, Object> attributes() {
+		return this.exchange.getAttributes();
+	}
+
 	@Override
 	public List<String> queryParams(String name) {
 		List<String> queryParams = request().getQueryParams().get(name);
@@ -152,6 +157,10 @@ class DefaultServerRequest implements ServerRequest {
 		return this.exchange;
 	}
 
+	@Override
+	public String toString() {
+		return String.format("%s %s", method(), path());
+	}
 
 	private class DefaultHeaders implements Headers {
 
@@ -205,6 +214,11 @@ class DefaultServerRequest implements ServerRequest {
 		public HttpHeaders asHttpHeaders() {
 			return HttpHeaders.readOnlyHttpHeaders(delegate());
 		}
+
+		@Override
+		public String toString() {
+			return delegate().toString();
+		}
 	}
 
 }

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

@@ -57,8 +57,13 @@ public interface RequestPredicate {
 			}
 
 			@Override
-			public ServerRequest subRequest(ServerRequest request) {
-				return other.subRequest(RequestPredicate.this.subRequest(request));
+			public ServerRequest nestRequest(ServerRequest request) {
+				return other.nestRequest(RequestPredicate.this.nestRequest(request));
+			}
+
+			@Override
+			public String toString() {
+				return String.format("(%s && %s)", RequestPredicate.this, other);
 			}
 		};
 	}
@@ -76,16 +81,47 @@ public interface RequestPredicate {
 	 * Returns a composed request predicate that tests against both this predicate OR the {@code other} predicate.
 	 * When evaluating the composed predicate, if this predicate is {@code true}, then the {@code other} predicate
 	 * is not evaluated.
-
 	 * @param other a predicate that will be logically-ORed with this predicate
 	 * @return a predicate composed of this predicate OR the {@code other} predicate
 	 */
 	default RequestPredicate or(RequestPredicate other) {
 		Assert.notNull(other, "'other' must not be null");
-		return (t) -> test(t) || other.test(t);
+		return new RequestPredicate() {
+			@Override
+			public boolean test(ServerRequest t) {
+				return RequestPredicate.this.test(t) || other.test(t);
+			}
+
+			@Override
+			public ServerRequest nestRequest(ServerRequest request) {
+				if (RequestPredicate.this.test(request)) {
+					return RequestPredicate.this.nestRequest(request);
+				}
+				else if (other.test(request)) {
+					return other.nestRequest(request);
+				}
+				else {
+					throw new IllegalStateException("Neither " + RequestPredicate.this.toString() +
+							" nor " + other + "matches");
+				}
+			}
+
+			@Override
+			public String toString() {
+				return String.format("(%s || %s)", RequestPredicate.this, other);
+			}
+		};
 	}
 
-	default ServerRequest subRequest(ServerRequest request) {
+	/**
+	 * Transforms the given request into a request used for a nested route. For instance, a
+	 * path-based predicate can return a {@code ServerRequest} with a nested path.
+	 * <p>Default implementation returns the given path.
+	 * @param request the request to be nested
+	 * @return the nested request
+	 * @see RouterFunctions#nest(RequestPredicate, RouterFunction)
+	 */
+	default ServerRequest nestRequest(ServerRequest request) {
 		return request;
 	}
 }

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

@@ -26,6 +26,8 @@ import java.util.Set;
 import java.util.function.Function;
 import java.util.function.Predicate;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import reactor.core.publisher.Flux;
 import reactor.core.publisher.Mono;
 
@@ -33,6 +35,7 @@ import org.springframework.http.HttpMethod;
 import org.springframework.http.MediaType;
 import org.springframework.http.server.reactive.ServerHttpRequest;
 import org.springframework.util.Assert;
+import org.springframework.util.StringUtils;
 import org.springframework.web.reactive.function.BodyExtractor;
 import org.springframework.web.server.WebSession;
 import org.springframework.web.util.UriUtils;
@@ -48,6 +51,8 @@ import org.springframework.web.util.patterns.PathPatternParser;
  */
 public abstract class RequestPredicates {
 
+	private static final Log logger = LogFactory.getLog(RequestPredicates.class);
+
 	private static final PathPatternParser DEFAULT_PATTERN_PARSER = new PathPatternParser();
 
 	/**
@@ -119,11 +124,21 @@ public abstract class RequestPredicates {
 	public static RequestPredicate contentType(MediaType... mediaTypes) {
 		Assert.notEmpty(mediaTypes, "'mediaTypes' must not be empty");
 		Set<MediaType> mediaTypeSet = new HashSet<>(Arrays.asList(mediaTypes));
-		return headers(headers -> {
-			MediaType contentType = headers.contentType().orElse(MediaType.APPLICATION_OCTET_STREAM);
-			return mediaTypeSet.stream()
-					.anyMatch(mediaType -> mediaType.includes(contentType));
+		return headers(new Predicate<ServerRequest.Headers>() {
+			@Override
+			public boolean test(ServerRequest.Headers headers) {
+				MediaType contentType =
+						headers.contentType().orElse(MediaType.APPLICATION_OCTET_STREAM);
+				boolean match = mediaTypeSet.stream()
+						.anyMatch(mediaType -> mediaType.includes(contentType));
+				traceMatch("Content-Type", mediaTypeSet, contentType, match);
+				return match;
+			}
 
+			@Override
+			public String toString() {
+				return String.format("Content-Type: %s", mediaTypeSet);
+			}
 		});
 	}
 
@@ -138,12 +153,23 @@ public abstract class RequestPredicates {
 	public static RequestPredicate accept(MediaType... mediaTypes) {
 		Assert.notEmpty(mediaTypes, "'mediaTypes' must not be empty");
 		Set<MediaType> mediaTypeSet = new HashSet<>(Arrays.asList(mediaTypes));
-		return headers(headers -> {
-			List<MediaType> acceptedMediaTypes = headers.accept();
-			MediaType.sortBySpecificityAndQuality(acceptedMediaTypes);
-			return acceptedMediaTypes.stream()
-					.anyMatch(acceptedMediaType -> mediaTypeSet.stream()
-							.anyMatch(acceptedMediaType::isCompatibleWith));
+		return headers(new Predicate<ServerRequest.Headers>() {
+			@Override
+			public boolean test(ServerRequest.Headers headers) {
+				List<MediaType> acceptedMediaTypes = headers.accept();
+				MediaType.sortBySpecificityAndQuality(acceptedMediaTypes);
+				boolean match = acceptedMediaTypes.stream()
+						.anyMatch(acceptedMediaType -> mediaTypeSet.stream()
+								.anyMatch(acceptedMediaType::isCompatibleWith));
+				traceMatch("Accept", mediaTypeSet, acceptedMediaTypes, match);
+				return match;
+			}
+
+			@Override
+			public String toString() {
+				return String.format("Accept: %s", mediaTypeSet);
+			}
+
 		});
 	}
 
@@ -238,7 +264,11 @@ public abstract class RequestPredicates {
 	 */
 	public static RequestPredicate pathExtension(String extension) {
 		Assert.notNull(extension, "'extension' must not be null");
-		return pathExtension(extension::equalsIgnoreCase);
+		return pathExtension(pathExtension -> {
+			boolean match = extension.equalsIgnoreCase(pathExtension);
+			traceMatch("Extension", extension, pathExtension, match);
+			return match;
+		});
 	}
 
 	/**
@@ -289,6 +319,14 @@ public abstract class RequestPredicates {
 		};
 	}
 
+	private static void traceMatch(String prefix, Object desired, Object actual, boolean match) {
+		if (logger.isTraceEnabled()) {
+			String message = String.format("%s \"%s\" %s against value \"%s\"",
+					prefix, desired, match ? "matches" : "does not match", actual);
+			logger.trace(message);
+		}
+	}
+
 
 	private static class HttpMethodPredicate implements RequestPredicate {
 
@@ -301,7 +339,14 @@ public abstract class RequestPredicates {
 
 		@Override
 		public boolean test(ServerRequest request) {
-			return this.httpMethod == request.method();
+			boolean match = this.httpMethod == request.method();
+			traceMatch("Method", this.httpMethod, request.method(), match);
+			return match;
+		}
+
+		@Override
+		public String toString() {
+			return this.httpMethod.toString();
 		}
 	}
 
@@ -317,12 +362,11 @@ public abstract class RequestPredicates {
 		@Override
 		public boolean test(ServerRequest request) {
 			String path = request.path();
-			if (this.pattern.matches(path)) {
-				if (request instanceof DefaultServerRequest) {
-					DefaultServerRequest defaultRequest = (DefaultServerRequest) request;
-					Map<String, String> uriTemplateVariables = this.pattern.matchAndExtract(path);
-					defaultRequest.exchange().getAttributes().put(RouterFunctions.URI_TEMPLATE_VARIABLES_ATTRIBUTE, uriTemplateVariables);
-				}
+			boolean match = this.pattern.matches(path);
+			traceMatch("Pattern", this.pattern.getPatternString(), path, match);
+			if (match) {
+				Map<String, String> uriTemplateVariables = this.pattern.matchAndExtract(path);
+				request.attributes().put(RouterFunctions.URI_TEMPLATE_VARIABLES_ATTRIBUTE, uriTemplateVariables);
 				return true;
 			}
 			else {
@@ -331,11 +375,19 @@ public abstract class RequestPredicates {
 		}
 
 		@Override
-		public ServerRequest subRequest(ServerRequest request) {
+		public ServerRequest nestRequest(ServerRequest request) {
 			String requestPath = request.path();
 			String subPath = this.pattern.extractPathWithinPattern(requestPath);
+			if (!subPath.startsWith("/")) {
+				subPath = "/" + subPath;
+			}
 			return new SubPathServerRequestWrapper(request, subPath);
 		}
+
+		@Override
+		public String toString() {
+			return this.pattern.getPatternString();
+		}
 	}
 
 	private static class HeadersPredicate implements RequestPredicate {
@@ -351,6 +403,11 @@ public abstract class RequestPredicates {
 		public boolean test(ServerRequest request) {
 			return this.headersPredicate.test(request.headers());
 		}
+
+		@Override
+		public String toString() {
+			return this.headersPredicate.toString();
+		}
 	}
 
 	private static class SubPathServerRequestWrapper implements ServerRequest {
@@ -409,6 +466,11 @@ public abstract class RequestPredicates {
 			return this.request.attribute(name);
 		}
 
+		@Override
+		public Map<String, Object> attributes() {
+			return this.request.attributes();
+		}
+
 		@Override
 		public Optional<String> queryParam(String name) {
 			return this.request.queryParam(name);
@@ -433,5 +495,11 @@ public abstract class RequestPredicates {
 		public Mono<WebSession> session() {
 			return this.request.session();
 		}
+
+		@Override
+		public String toString() {
+			return String.format("%s %s", method(), path());
+		}
+
 	}
 }

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

@@ -19,6 +19,8 @@ package org.springframework.web.reactive.function.server;
 import java.util.Map;
 import java.util.function.Function;
 
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
 import reactor.core.publisher.Mono;
 
 import org.springframework.core.io.Resource;
@@ -52,6 +54,8 @@ import org.springframework.web.server.adapter.WebHttpHandlerBuilder;
  */
 public abstract class RouterFunctions {
 
+	private static final Log logger = LogFactory.getLog(RouterFunctions.class);
+
 	/**
 	 * Name of the {@link ServerWebExchange} attribute that contains the {@link ServerRequest}.
 	 */
@@ -90,7 +94,18 @@ public abstract class RouterFunctions {
 		Assert.notNull(predicate, "'predicate' must not be null");
 		Assert.notNull(handlerFunction, "'handlerFunction' must not be null");
 
-		return request -> predicate.test(request) ? Mono.just(handlerFunction) : Mono.empty();
+		return request -> {
+			if (predicate.test(request)) {
+				if (logger.isDebugEnabled()) {
+					logger.debug(String.format("Predicate \"%s\" matches against \"%s\"",
+							predicate, request));
+				}
+				return Mono.just(handlerFunction);
+			}
+			else {
+				return Mono.empty();
+			}
+		};
 	}
 
 	/**
@@ -124,7 +139,11 @@ public abstract class RouterFunctions {
 
 		return request -> {
 			if (predicate.test(request)) {
-				ServerRequest subRequest = predicate.subRequest(request);
+				if (logger.isDebugEnabled()) {
+					logger.debug(String.format("Nested predicate \"%s\" matches against \"%s\"",
+							predicate, request));
+				}
+				ServerRequest subRequest = predicate.nestRequest(request);
 				return routerFunction.route(subRequest);
 			}
 			else {

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

@@ -113,6 +113,12 @@ public interface ServerRequest {
 	 */
 	<T> Optional<T> attribute(String name);
 
+	/**
+	 * Return a mutable map of request attributes.
+	 * @return the request attributes
+	 */
+	Map<String, Object> attributes();
+
 	/**
 	 * Return the first query parameter with the given name, if present.
 	 * @param name the parameter name

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

@@ -114,6 +114,11 @@ public class ServerRequestWrapper implements ServerRequest {
 		return this.delegate.attribute(name);
 	}
 
+	@Override
+	public Map<String, Object> attributes() {
+		return this.delegate.attributes();
+	}
+
 	@Override
 	public Optional<String> queryParam(String name) {
 		return this.delegate.queryParam(name);

spring-webflux/src/test/java/org/springframework/web/reactive/function/server/MockServerRequest.java

@@ -29,6 +29,7 @@ import java.util.Locale;
 import java.util.Map;
 import java.util.Optional;
 import java.util.OptionalLong;
+import java.util.concurrent.ConcurrentHashMap;
 
 import reactor.core.publisher.Flux;
 import reactor.core.publisher.Mono;
@@ -127,6 +128,11 @@ public class MockServerRequest implements ServerRequest {
 		return Optional.ofNullable((S) this.attributes.get(name));
 	}
 
+	@Override
+	public Map<String, Object> attributes() {
+		return this.attributes;
+	}
+
 	@Override
 	public List<String> queryParams(String name) {
 		return Collections.unmodifiableList(this.queryParams.get(name));
@@ -182,7 +188,7 @@ public class MockServerRequest implements ServerRequest {
 
 		private Object body;
 
-		private Map<String, Object> attributes = new LinkedHashMap<>();
+		private Map<String, Object> attributes = new ConcurrentHashMap<>();
 
 		private MultiValueMap<String, String> queryParams = new LinkedMultiValueMap<>();