Truncate logged encoded and decoded values if necessary

rstoyanchev · rstoyanchev · commit e62298eaadf2 · 2018-09-14T12:20:03.000-04:00
At DEBUG show up to 100 chars, at TRACE show full formatted value.

Note that the formatValue helper method is duplicated a number of times
in this commit. A utility method will likely be added in spring-core
through an extra commit.

Issue: SPR-17254
diff --git a/spring-core/src/main/java/org/springframework/core/codec/CharSequenceEncoder.java b/spring-core/src/main/java/org/springframework/core/codec/CharSequenceEncoder.java
@@ -70,7 +70,13 @@ public Flux<DataBuffer> encode(Publisher<? extends CharSequence> inputStream,
 		return Flux.from(inputStream).map(charSequence -> {
 			if (logger.isDebugEnabled() && !Hints.isLoggingSuppressed(hints)) {
 				String logPrefix = Hints.getLogPrefix(hints);
-				logger.debug(logPrefix + "Writing '" + charSequence + "'");
+				String s = logPrefix + "Writing " + formatValue(charSequence, logger.isTraceEnabled());
+				if (logger.isTraceEnabled()) {
+					logger.trace(s);
+				}
+				else {
+					logger.debug(s);
+				}
 			}
 			CharBuffer charBuffer = CharBuffer.wrap(charSequence);
 			ByteBuffer byteBuffer = charset.encode(charBuffer);
@@ -89,6 +95,15 @@ private Charset getCharset(@Nullable MimeType mimeType) {
 		return charset;
 	}
 
+	private String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
+
 	/**
 	 * Create a {@code CharSequenceEncoder} that supports only "text/plain".
 	 */
diff --git a/spring-core/src/main/java/org/springframework/core/codec/StringDecoder.java b/spring-core/src/main/java/org/springframework/core/codec/StringDecoder.java
@@ -207,7 +207,13 @@ protected String decodeDataBuffer(DataBuffer dataBuffer, ResolvableType elementT
 		DataBufferUtils.release(dataBuffer);
 		String value = charBuffer.toString();
 		if (logger.isDebugEnabled()) {
-			logger.debug(Hints.getLogPrefix(hints) + "Decoded '" + value + "'");
+			String s = Hints.getLogPrefix(hints) + "Decoded " + formatValue(value, logger.isTraceEnabled());
+			if (logger.isTraceEnabled()) {
+				logger.trace(s);
+			}
+			else {
+				logger.debug(s);
+			}
 		}
 		return value;
 	}
@@ -221,6 +227,14 @@ private static Charset getCharset(@Nullable MimeType mimeType) {
 		}
 	}
 
+	private String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 
 	/**
 	 * Create a {@code StringDecoder} for {@code "text/plain"}.
diff --git a/spring-web/src/main/java/org/springframework/http/codec/FormHttpMessageReader.java b/spring-web/src/main/java/org/springframework/http/codec/FormHttpMessageReader.java
@@ -108,15 +108,26 @@ public Mono<MultiValueMap<String, String>> readMono(ResolvableType elementType,
 					String body = charBuffer.toString();
 					DataBufferUtils.release(buffer);
 					MultiValueMap<String, String> formData = parseFormData(charset, body);
-					if (logger.isDebugEnabled()) {
-						String details = isEnableLoggingRequestDetails() ?
-								formData.toString() : "form fields " + formData.keySet() + " (content masked)";
-						logger.debug(Hints.getLogPrefix(hints) + "Read " + details);
-					}
+					logFormData(formData, hints);
 					return formData;
 				});
 	}
 
+	private void logFormData(MultiValueMap<String, String> formData, Map<String, Object> hints) {
+		if (logger.isDebugEnabled()) {
+			String s = Hints.getLogPrefix(hints) + "Read " +
+					(isEnableLoggingRequestDetails() ?
+							formatValue(formData, logger.isTraceEnabled()) :
+							"form fields " + formData.keySet() + " (content masked)");
+			if (logger.isTraceEnabled()) {
+				logger.trace(s);
+			}
+			else {
+				logger.debug(s);
+			}
+		}
+	}
+
 	private Charset getMediaTypeCharset(@Nullable MediaType mediaType) {
 		if (mediaType != null && mediaType.getCharset() != null) {
 			return mediaType.getCharset();
diff --git a/spring-web/src/main/java/org/springframework/http/codec/FormHttpMessageWriter.java b/spring-web/src/main/java/org/springframework/http/codec/FormHttpMessageWriter.java
@@ -132,9 +132,15 @@ public Mono<Void> write(Publisher<? extends MultiValueMap<String, String>> input
 
 		return Mono.from(inputStream).flatMap(form -> {
 			if (logger.isDebugEnabled()) {
-				String details = isEnableLoggingRequestDetails() ?
-						form.toString() : "form fields " + form.keySet() + " (content masked)";
-				logger.debug(Hints.getLogPrefix(hints) + "Writing " + details);
+				String s = Hints.getLogPrefix(hints) + "Writing " +
+						(isEnableLoggingRequestDetails() ?
+								form.toString() : "form fields " + form.keySet() + " (content masked)");
+				if (logger.isTraceEnabled()) {
+					logger.trace(s);
+				}
+				else {
+					logger.debug(s);
+				}
 			}
 			String value = serializeForm(form, charset);
 			ByteBuffer byteBuffer = charset.encode(value);
diff --git a/spring-web/src/main/java/org/springframework/http/codec/LoggingCodecSupport.java b/spring-web/src/main/java/org/springframework/http/codec/LoggingCodecSupport.java
@@ -19,6 +19,7 @@
 import org.apache.commons.logging.Log;
 
 import org.springframework.http.HttpLogging;
+import org.springframework.lang.Nullable;
 
 /**
  * Base class for {@link org.springframework.core.codec.Encoder},
@@ -55,4 +56,20 @@ public boolean isEnableLoggingRequestDetails() {
 		return this.enableLoggingRequestDetails;
 	}
 
+	/**
+	 * Format the given value via {{toString()}}, either in full or truncated
+	 * if it has 100 or more characters.
+	 * @param value the value to format
+	 * @param logFullValue whether to log in full or truncate if necessary
+	 * @return the formatted value
+	 * @since 5.1
+	 */
+	protected String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 }
diff --git a/spring-web/src/main/java/org/springframework/http/codec/json/AbstractJackson2Decoder.java b/spring-web/src/main/java/org/springframework/http/codec/json/AbstractJackson2Decoder.java
@@ -116,7 +116,14 @@ private Flux<Object> decodeInternal(Flux<TokenBuffer> tokens, ResolvableType ele
 			try {
 				Object value = reader.readValue(tokenBuffer.asParser(getObjectMapper()));
 				if (logger.isDebugEnabled() && !Hints.isLoggingSuppressed(hints)) {
-					logger.debug(Hints.getLogPrefix(hints) +"Decoded [" + value + "]");
+					boolean traceOn = logger.isTraceEnabled();
+					String s = Hints.getLogPrefix(hints) + "Decoded [" + formatValue(value, traceOn) + "]";
+					if (traceOn) {
+						logger.trace(s);
+					}
+					else {
+						logger.debug(s);
+					}
 				}
 				return value;
 			}
diff --git a/spring-web/src/main/java/org/springframework/http/codec/json/AbstractJackson2Encoder.java b/spring-web/src/main/java/org/springframework/http/codec/json/AbstractJackson2Encoder.java
@@ -142,7 +142,14 @@ private DataBuffer encodeValue(Object value, @Nullable MimeType mimeType, DataBu
 			ResolvableType elementType, @Nullable Map<String, Object> hints, JsonEncoding encoding) {
 
 		if (logger.isDebugEnabled() && !Hints.isLoggingSuppressed(hints)) {
-			logger.debug(Hints.getLogPrefix(hints) + "Encoding [" + value + "]");
+			boolean traceOn = logger.isTraceEnabled();
+			String s = Hints.getLogPrefix(hints) + "Encoding [" + formatValue(value, traceOn) + "]";
+			if (traceOn) {
+				logger.trace(s);
+			}
+			else {
+				logger.debug(s);
+			}
 		}
 
 		JavaType javaType = getJavaType(elementType.getType(), null);
diff --git a/spring-web/src/main/java/org/springframework/http/codec/json/Jackson2CodecSupport.java b/spring-web/src/main/java/org/springframework/http/codec/json/Jackson2CodecSupport.java
@@ -125,4 +125,12 @@ protected MethodParameter getParameter(ResolvableType type) {
 	@Nullable
 	protected abstract <A extends Annotation> A getAnnotation(MethodParameter parameter, Class<A> annotType);
 
+	String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 }
diff --git a/spring-web/src/main/java/org/springframework/http/codec/multipart/MultipartHttpMessageReader.java b/spring-web/src/main/java/org/springframework/http/codec/multipart/MultipartHttpMessageReader.java
@@ -95,9 +95,15 @@ public Mono<MultiValueMap<String, Part>> readMono(ResolvableType elementType,
 				.collectMultimap(Part::name)
 				.doOnNext(map -> {
 					if (logger.isDebugEnabled()) {
-						String details = isEnableLoggingRequestDetails() ?
-								map.toString() : "parts " + map.keySet() + " (content masked)";
-						logger.debug(Hints.getLogPrefix(hints) + "Parsed " + details);
+						String s = Hints.getLogPrefix(hints) + "Parsed " +
+								(isEnableLoggingRequestDetails() ?
+										map.toString() : "parts " + map.keySet() + " (content masked)");
+						if (logger.isTraceEnabled()) {
+							logger.trace(s);
+						}
+						else {
+							logger.debug(s);
+						}
 					}
 				})
 				.map(this::toMultiValueMap);
diff --git a/spring-web/src/main/java/org/springframework/http/codec/multipart/MultipartHttpMessageWriter.java b/spring-web/src/main/java/org/springframework/http/codec/multipart/MultipartHttpMessageWriter.java
@@ -226,9 +226,15 @@ private Mono<Void> writeMultipart(
 		outputMessage.getHeaders().setContentType(new MediaType(MediaType.MULTIPART_FORM_DATA, params));
 
 		if (logger.isDebugEnabled()) {
-			String details = isEnableLoggingRequestDetails() ?
-					map.toString() : "parts " + map.keySet() + " (content masked)";
-			logger.debug(Hints.getLogPrefix(hints) + "Encoding " + details);
+			String s = Hints.getLogPrefix(hints) + "Encoding " +
+					(isEnableLoggingRequestDetails() ?
+							map.toString() : "parts " + map.keySet() + " (content masked)");
+			if (logger.isTraceEnabled()) {
+				logger.trace(s);
+			}
+			else {
+				logger.debug(s);
+			}
 		}
 
 		Flux<DataBuffer> body = Flux.fromIterable(map.entrySet())
diff --git a/spring-web/src/main/java/org/springframework/http/codec/multipart/SynchronossPartHttpMessageReader.java b/spring-web/src/main/java/org/springframework/http/codec/multipart/SynchronossPartHttpMessageReader.java
@@ -96,9 +96,14 @@ public Flux<Part> read(ResolvableType elementType, ReactiveHttpInputMessage mess
 		return Flux.create(new SynchronossPartGenerator(message, this.bufferFactory, this.streamStorageFactory))
 				.doOnNext(part -> {
 					if (logger.isDebugEnabled() && !Hints.isLoggingSuppressed(hints)) {
-						String details = isEnableLoggingRequestDetails() ?
-								part.toString() : "parts '" + part.name() + "' (content masked)";
-						logger.debug(Hints.getLogPrefix(hints) + "Parsed " + details);
+						String s = Hints.getLogPrefix(hints) + "Parsed " + (isEnableLoggingRequestDetails() ?
+								part.toString() : "parts '" + part.name() + "' (content masked)");
+						if (logger.isTraceEnabled()) {
+							logger.trace(s);
+						}
+						else {
+							logger.debug(s);
+						}
 					}
 				});
 	}
diff --git a/spring-web/src/main/java/org/springframework/http/codec/xml/Jaxb2XmlDecoder.java b/spring-web/src/main/java/org/springframework/http/codec/xml/Jaxb2XmlDecoder.java
@@ -108,7 +108,14 @@ public Flux<Object> decode(Publisher<DataBuffer> inputStream, ResolvableType ele
 		return splitEvents.map(events -> {
 			Object value = unmarshal(events, outputClass);
 			if (logger.isDebugEnabled()) {
-				logger.debug(Hints.getLogPrefix(hints) + "Decoded [" + value + "]");
+				boolean traceOn = logger.isTraceEnabled();
+				String s = Hints.getLogPrefix(hints) + "Decoded [" + formatValue(value, traceOn) + "]";
+				if (traceOn) {
+					logger.trace(s);
+				}
+				else {
+					logger.debug(s);
+				}
 			}
 			return value;
 		});
@@ -206,6 +213,14 @@ Flux<List<XMLEvent>> split(Flux<XMLEvent> xmlEventFlux, QName desiredName) {
 		return xmlEventFlux.flatMap(new SplitFunction(desiredName));
 	}
 
+	String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 
 	private static class SplitFunction implements Function<XMLEvent, Publisher<? extends List<XMLEvent>>> {
 
diff --git a/spring-web/src/main/java/org/springframework/http/codec/xml/Jaxb2XmlEncoder.java b/spring-web/src/main/java/org/springframework/http/codec/xml/Jaxb2XmlEncoder.java
@@ -79,7 +79,14 @@ protected Flux<DataBuffer> encode(Object value, DataBufferFactory dataBufferFact
 			ResolvableType type, @Nullable MimeType mimeType, @Nullable Map<String, Object> hints) {
 		try {
 			if (logger.isDebugEnabled() && !Hints.isLoggingSuppressed(hints)) {
-				logger.debug(Hints.getLogPrefix(hints) + "Encoding [" + value + "]");
+				boolean traceOn = logger.isTraceEnabled();
+				String s = Hints.getLogPrefix(hints) + "Encoding [" + formatValue(value, traceOn) + "]";
+				if (traceOn) {
+					logger.trace(s);
+				}
+				else {
+					logger.debug(s);
+				}
 			}
 			DataBuffer buffer = dataBufferFactory.allocateBuffer(1024);
 			OutputStream outputStream = buffer.asOutputStream();
@@ -97,4 +104,12 @@ protected Flux<DataBuffer> encode(Object value, DataBufferFactory dataBufferFact
 		}
 	}
 
+	String formatValue(@Nullable Object value, boolean logFullValue) {
+		if (value == null) {
+			return "";
+		}
+		String s = value instanceof CharSequence ? "\"" + value + "\"" : value.toString();
+		return logFullValue || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 }
diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/AbstractMessageConverterMethodArgumentResolver.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/AbstractMessageConverterMethodArgumentResolver.java
@@ -224,8 +224,15 @@ protected <T> Object readWithMessageConverters(HttpInputMessage inputMessage, Me
 		}
 
 		if (logger.isDebugEnabled()) {
-			logger.debug("Read \"" + contentType + "\" to " +
-					"[" + (body instanceof String ? "\"" + body + "\"" : body) + "]");
+			boolean traceOn = logger.isTraceEnabled();
+			String s = "Read \"" + contentType + "\" to [" +
+					RequestMappingHandlerAdapter.formatValue(body, traceOn) + "]";
+			if (traceOn) {
+				logger.trace(s);
+			}
+			else {
+				logger.debug(s);
+			}
 		}
 
 		return body;
diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/AbstractMessageConverterMethodProcessor.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/AbstractMessageConverterMethodProcessor.java
@@ -281,7 +281,14 @@ else if (mediaType.equals(MediaType.ALL) || mediaType.equals(MEDIA_TYPE_APPLICAT
 							inputMessage, outputMessage);
 					if (body != null) {
 						if (logger.isDebugEnabled()) {
-							logger.debug("Writing [" + formatValue(body) + "]");
+							boolean traceOn = logger.isTraceEnabled();
+							String s = "Writing [" + RequestMappingHandlerAdapter.formatValue(body, traceOn) + "]";
+							if (traceOn) {
+								logger.trace(s);
+							}
+							else {
+								logger.debug(s);
+							}
 						}
 						addContentDispositionHeader(inputMessage, outputMessage);
 						if (genericConverter != null) {
@@ -398,10 +405,6 @@ private MediaType getMostSpecificMediaType(MediaType acceptType, MediaType produ
 		return (MediaType.SPECIFICITY_COMPARATOR.compare(acceptType, produceTypeToUse) <= 0 ? acceptType : produceTypeToUse);
 	}
 
-	static String formatValue(Object body) {
-		return (body instanceof CharSequence ? "\"" + body + "\"" : body.toString());
-	}
-
 	/**
 	 * Check if the path has a file extension and whether the extension is
 	 * either {@link #WHITELISTED_EXTENSIONS whitelisted} or explicitly
diff --git a/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/RequestMappingHandlerAdapter.java b/spring-webmvc/src/main/java/org/springframework/web/servlet/mvc/method/annotation/RequestMappingHandlerAdapter.java
@@ -885,8 +885,13 @@ protected ModelAndView invokeHandlerMethod(HttpServletRequest request,
 				mavContainer = (ModelAndViewContainer) asyncManager.getConcurrentResultContext()[0];
 				asyncManager.clearConcurrentResult();
 				if (logger.isDebugEnabled()) {
-					String formatted = AbstractMessageConverterMethodProcessor.formatValue(result);
-					logger.debug("Resume with async result [" + formatted + "]");
+					String s = "Resume with async result [" + formatValue(result, logger.isTraceEnabled()) + "]";
+					if (logger.isTraceEnabled()) {
+						logger.trace(s);
+					}
+					else {
+						logger.debug(s);
+					}
 				}
 				invocableMethod = invocableMethod.wrapConcurrentResult(result);
 			}
@@ -1019,4 +1024,12 @@ private ModelAndView getModelAndView(ModelAndViewContainer mavContainer,
 		return mav;
 	}
 
+	static String formatValue(@Nullable Object body, boolean logFullBody) {
+		if (body == null) {
+			return "";
+		}
+		String s = body instanceof CharSequence ? "\"" + body + "\"" : body.toString();
+		return logFullBody || s.length() < 100 ? s : s.substring(0, 100) + " (truncated)...";
+	}
+
 }
