Fine-tune and review logging output

[philwebb]

See SPR-16946.

[philwebb]

/cc @rstoyanchev

[bclozel]

Also, we should track the results of SPR-16954.

[rstoyanchev]

A few concrete items:

1. Logging under org.springframework.core.codec, org.springframework.http, org.springframework.web is now explicitly designed to be compact at DEBUG level, and not require changing individual package settings. It should be possible, and helpful, to have that enabled out of the box to with devtools. If that is not the case, e.g. if we've missed or re-intorduce anything in the future that causes a lot of output at DEBUG, we can treat it as a framework issue.

2. DispatcherServlet has a new enableLoggingRequestDetails property that could be on with devtools. In WebFlux the same property is under CodecConfigurer#defaultCodecs which applies to both server side (WebFluxConfigurer) and client side (WebClient.Builder`).

3. DefaultErrorWebExceptionHandler can make its log message that prints the status code more minimal. HttpWebHandlerAdapter logs detailed response information including status.

4. Now that ServerWebExchange has the getLogPrefix() method, this could be used to prepend any log messages from Spring Boot with access to ServerWebExchange. This is what it looks like otherwise:

[reactor-http-server-epoll-6] 54:52 o.s.w.s.a.HttpWebHandlerAdapter: [83b08de0] HTTP GET "/carsss", headers={masked}
[reactor-http-server-epoll-6] 54:52 o.s.w.r.h.SimpleUrlHandlerMapping: [83b08de0] Mapped to ResourceWebHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/"]
[reactor-http-server-epoll-6] 54:52 o.s.w.r.r.ResourceWebHandler: [83b08de0] Resource not found
[reactor-http-server-epoll-6] 54:52 o.s.w.r.f.s.RouterFunctions: [83b08de0] Matched org.springframework.web.reactive.function.server.RequestPredicates$$Lambda$659/369798142@1b4d833b
[reactor-http-server-epoll-6] 54:52 o.s.b.a.w.r.e.DefaultErrorWebExceptionHandler: Failed to handle request [GET http://localhost:8081/carsss]: 404 NOT_FOUND

[philwebb]

See also https://github.com/spring-projects/spring-framework/wiki/Logging

[rstoyanchev]

The following output appears for when an error mapping is involved:

[reactor-http-server-epoll-6] 54:52 o.s.w.s.a.HttpWebHandlerAdapter: [83b08de0] HTTP GET "/carsss", headers={masked}
[reactor-http-server-epoll-6] 54:52 o.s.w.r.h.SimpleUrlHandlerMapping: [83b08de0] Mapped to ResourceWebHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/"]
[reactor-http-server-epoll-6] 54:52 o.s.w.r.r.ResourceWebHandler: [83b08de0] Resource not found
[reactor-http-server-epoll-6] 54:52 o.s.w.r.f.s.RouterFunctions: [83b08de0] Matched org.springframework.web.reactive.function.server.RequestPredicates$$Lambda$659/369798142@1b4d833b
[reactor-http-server-epoll-6] 54:52 o.s.b.a.w.r.e.DefaultErrorWebExceptionHandler: Failed to handle request [GET http://localhost:8081/carsss]: 404 NOT_FOUND
[reactor-http-server-epoll-6] 54:52 o.s.w.HTTP: [83b08de0] Encoding [{timestamp=Tue Jul 17 08:54:52 EDT 2018, path=/carsss, status=404, error=Not Found, message=null, trace=org.springframework.web.server.ResponseStatusException: 404 NOT_FOUND
...
long stack trace here...
...
[reactor-http-server-epoll-6] 54:52 o.s.w.s.a.HttpWebHandlerAdapter: [83b08de0] Completed 404 NOT_FOUND, headers={masked}
[reactor-http-server-epoll-6] 54:52 o.s.w.HTTP: [83b08de0] Handling completed

Notice the "Matched ... RequestPredicate" message which is logged in the Spring Framework at TRACE level. It's not clear that what's going is error mapping. It would help to a) have an extra message before that which says something like "routing error" or "mapping error", and b) maybe the predicate could be refactored into an actual inner class instead of a lambda so it appears under a more readable name or even a toString method to choose the name.

[bclozel]

I've just applied the following changes to my working copy:

1. devtools enables DEBUG logging for "org.springframework.web"
2. updated DefaultErrorWebExceptionHandler to align with the Framework changes (log prefix, etc)

Spring WebFlux

Given the following Controller, I've tested each endpoint to see the logging output.

@RestController
public class HomeController {

	@GetMapping("/")
	public Mono<String> greet(@RequestParam String name) {
		return Mono.just("Hello, " + name);
	}

	@GetMapping("/boom")
	public Mono<String> boom() {
		return Mono.error(new IllegalArgumentException("Something illegal"));
	}

	@GetMapping("/status")
	public Mono<String> status() {
		return Mono.error(new ResponseStatusException(HttpStatus.BAD_REQUEST));
	}
}

23:01:40.095 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Included patterns for restart : []
23:01:40.102 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Excluded patterns for restart : [/spring-boot-starter-[\w-]+/, /spring-boot/target/classes/, /spring-boot-starter/target/classes/, /spring-boot-devtools/target/classes/, /spring-boot-actuator/target/classes/, /spring-boot-autoconfigure/target/classes/]
23:01:40.102 [main] DEBUG org.springframework.boot.devtools.restart.ChangeableUrls - Matching URLs for reloading : [file:/Users/bclozel/workspace/tmp/demo/target/classes/]
sun.reflect.ReflectionFactory@498d318c

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::  (v2.1.0.BUILD-SNAPSHOT)

2018-07-26 23:01:40.467  INFO 8111 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication on Brians-MacBook-Pro.local with PID 8111 (/Users/bclozel/workspace/tmp/demo/target/classes started by bclozel in /Users/bclozel/workspace/tmp/demo)
2018-07-26 23:01:40.469  INFO 8111 --- [  restartedMain] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-07-26 23:01:42.216 DEBUG 8111 --- [  restartedMain] s.w.r.r.m.a.RequestMappingHandlerMapping : 3 mappings in 'requestMappingHandlerMapping'
2018-07-26 23:01:42.245 DEBUG 8111 --- [  restartedMain] o.s.w.r.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
2018-07-26 23:01:42.541  INFO 8111 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 15 endpoint(s) beneath base path '/actuator'
2018-07-26 23:01:42.631 DEBUG 8111 --- [  restartedMain] o.s.w.r.r.m.a.ControllerMethodResolver   : ControllerAdvice beans: none
2018-07-26 23:01:42.699 DEBUG 8111 --- [  restartedMain] o.s.w.s.adapter.HttpWebHandlerAdapter    : enableLoggingRequestDetails='false': form data and headers will be masked to prevent unsafe logging of potentially sensitive data
2018-07-26 23:01:42.943  INFO 8111 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-07-26 23:01:43.083  INFO 8111 --- [  restartedMain] o.s.b.web.embedded.netty.NettyWebServer  : Netty started on port(s): 8080
2018-07-26 23:01:43.088  INFO 8111 --- [  restartedMain] com.example.demo.DemoApplication         : Started DemoApplication in 2.97 seconds (JVM running for 3.885)
2018-07-26 23:01:48.170 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] HTTP GET "/?name=Boot"
2018-07-26 23:01:48.203 DEBUG 8111 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [2840b753] Mapped to public reactor.core.publisher.Mono<java.lang.String> com.example.demo.HomeController.greet(java.lang.String)
2018-07-26 23:01:48.219 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'text/html' given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*]
2018-07-26 23:01:48.220 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [2840b753] 0..1 [java.lang.String]
2018-07-26 23:01:48.222 DEBUG 8111 --- [ctor-http-nio-2] o.s.core.codec.CharSequenceEncoder       : [2840b753] Writing 'Hello, Boot'
2018-07-26 23:01:48.236 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] Completed 200 OK
2018-07-26 23:01:51.067 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] HTTP GET "/"
2018-07-26 23:01:51.072 DEBUG 8111 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [2840b753] Mapped to public reactor.core.publisher.Mono<java.lang.String> com.example.demo.HomeController.greet(java.lang.String)
2018-07-26 23:01:51.083 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.method.InvocableHandlerMethod  : [2840b753] Could not resolve parameter [0] in public reactor.core.publisher.Mono<java.lang.String> com.example.demo.HomeController.greet(java.lang.String): 400 BAD_REQUEST "Required String parameter 'name' is not present"
2018-07-26 23:01:51.131 DEBUG 8111 --- [ctor-http-nio-2] org.springframework.web.HttpLogging      : [2840b753] Resolved [ServerWebInputException: 400 BAD_REQUEST "Required String parameter 'name' is not present"] for HTTP GET /
2018-07-26 23:01:51.135 DEBUG 8111 --- [ctor-http-nio-2] o.s.core.codec.CharSequenceEncoder       : [2840b753] Writing '<html><body><h1>Whitelabel Error Page</h1><p>This application has no configured error view, so you are seeing this as a fallback.</p><div id='created'>Thu Jul 26 23:01:51 CEST 2018</div><div>There was an unexpected error (type=Bad Request, status=400).</div><div>Required String parameter &#39;name&#39; is not present</div></body></html>'
2018-07-26 23:01:51.136 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] Completed 400 BAD_REQUEST
2018-07-26 23:01:55.403 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] HTTP GET "/status"
2018-07-26 23:01:55.407 DEBUG 8111 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [2840b753] Mapped to public reactor.core.publisher.Mono<java.lang.String> com.example.demo.HomeController.status()
2018-07-26 23:01:55.408 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'text/html' given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*]
2018-07-26 23:01:55.408 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [2840b753] 0..1 [java.lang.String]
2018-07-26 23:01:55.432 DEBUG 8111 --- [ctor-http-nio-2] org.springframework.web.HttpLogging      : [2840b753] Resolved [ResponseStatusException: 400 BAD_REQUEST] for HTTP GET /status
2018-07-26 23:01:55.432 DEBUG 8111 --- [ctor-http-nio-2] o.s.core.codec.CharSequenceEncoder       : [2840b753] Writing '<html><body><h1>Whitelabel Error Page</h1><p>This application has no configured error view, so you are seeing this as a fallback.</p><div id='created'>Thu Jul 26 23:01:55 CEST 2018</div><div>There was an unexpected error (type=Bad Request, status=400).</div></body></html>'
2018-07-26 23:01:55.434 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] Completed 400 BAD_REQUEST
2018-07-26 23:01:58.269 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] HTTP GET "/boom"
2018-07-26 23:01:58.272 DEBUG 8111 --- [ctor-http-nio-2] s.w.r.r.m.a.RequestMappingHandlerMapping : [2840b753] Mapped to public reactor.core.publisher.Mono<java.lang.String> com.example.demo.HomeController.boom()
2018-07-26 23:01:58.273 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : Using 'text/html' given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*]
2018-07-26 23:01:58.273 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.r.m.a.ResponseBodyResultHandler  : [2840b753] 0..1 [java.lang.String]
2018-07-26 23:01:58.293 DEBUG 8111 --- [ctor-http-nio-2] org.springframework.web.HttpLogging      : [2840b753] Resolved [IllegalArgumentException: Something illegal] for HTTP GET /boom
2018-07-26 23:01:58.294 DEBUG 8111 --- [ctor-http-nio-2] o.s.core.codec.CharSequenceEncoder       : [2840b753] Writing '<html><body><h1>Whitelabel Error Page</h1><p>This application has no configured error view, so you are seeing this as a fallback.</p><div id='created'>Thu Jul 26 23:01:58 CEST 2018</div><div>There was an unexpected error (type=Internal Server Error, status=500).</div><div>Something illegal</div></body></html>'
2018-07-26 23:01:58.295 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] Completed 500 INTERNAL_SERVER_ERROR
2018-07-26 23:02:01.861 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] HTTP GET "/notfound"
2018-07-26 23:02:01.865 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.handler.SimpleUrlHandlerMapping  : [2840b753] Mapped to ResourceWebHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/"]
2018-07-26 23:02:01.867 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.r.resource.ResourceWebHandler      : [2840b753] Resource not found
2018-07-26 23:02:01.880 DEBUG 8111 --- [ctor-http-nio-2] org.springframework.web.HttpLogging      : [2840b753] Resolved [ResponseStatusException: 404 NOT_FOUND] for HTTP GET /notfound
2018-07-26 23:02:01.881 DEBUG 8111 --- [ctor-http-nio-2] o.s.core.codec.CharSequenceEncoder       : [2840b753] Writing '<html><body><h1>Whitelabel Error Page</h1><p>This application has no configured error view, so you are seeing this as a fallback.</p><div id='created'>Thu Jul 26 23:02:01 CEST 2018</div><div>There was an unexpected error (type=Not Found, status=404).</div></body></html>'
2018-07-26 23:02:01.882 DEBUG 8111 --- [ctor-http-nio-2] o.s.w.s.adapter.HttpWebHandlerAdapter    : [2840b753] Completed 404 NOT_FOUND

Spring MVC

Same thing for Spring MVC

@RestController
public class MvcHomeController {

	@GetMapping("/")
	public String greet(@RequestParam String name) {
		return "Hello, " + name;
	}

	@GetMapping("/boom")
	public String boom() {
		throw new IllegalArgumentException("Something illegal");
	}

	@GetMapping("/status")
	public String status() {
		throw new ResponseStatusException(HttpStatus.BAD_REQUEST);
	}
}

/Library/Java/JavaVirtualMachines/jdk-9.0.1.jdk/Contents/Home/bin/java -XX:TieredStopAtLevel=1 -noverify -Dspring.output.ansi.enabled=always -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=56431 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=127.0.0.1 -Dspring.liveBeansView.mbeanDomain -Dspring.application.admin.enabled=true "-javaagent:/Users/bclozel/Library/Application Support/JetBrains/Toolbox/apps/IDEA-U/ch-1/182.3684.101/IntelliJ IDEA 2018.2 EAP.app/Contents/lib/idea_rt.jar=56432:/Users/bclozel/Library/Application Support/JetBrains/Toolbox/apps/IDEA-U/ch-1/182.3684.101/IntelliJ IDEA 2018.2 EAP.app/Contents/bin" -Dfile.encoding=UTF-8 -classpath /Users/bclozel/workspace/tmp/demo/target/classes:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-webflux/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-webflux-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-logging/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-logging-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar:/Users/bclozel/.m2/repository/ch/qos/logback/logback-core/1.2.3/logback-core-1.2.3.jar:/Users/bclozel/.m2/repository/org/apache/logging/log4j/log4j-to-slf4j/2.11.0/log4j-to-slf4j-2.11.0.jar:/Users/bclozel/.m2/repository/org/apache/logging/log4j/log4j-api/2.11.0/log4j-api-2.11.0.jar:/Users/bclozel/.m2/repository/org/slf4j/jul-to-slf4j/1.7.25/jul-to-slf4j-1.7.25.jar:/Users/bclozel/.m2/repository/javax/annotation/javax.annotation-api/1.3.2/javax.annotation-api-1.3.2.jar:/Users/bclozel/.m2/repository/org/yaml/snakeyaml/1.21/snakeyaml-1.21.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-json/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-json-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/core/jackson-databind/2.9.6/jackson-databind-2.9.6.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/core/jackson-annotations/2.9.0/jackson-annotations-2.9.0.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/core/jackson-core/2.9.6/jackson-core-2.9.6.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jdk8/2.9.6/jackson-datatype-jdk8-2.9.6.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/datatype/jackson-datatype-jsr310/2.9.6/jackson-datatype-jsr310-2.9.6.jar:/Users/bclozel/.m2/repository/com/fasterxml/jackson/module/jackson-module-parameter-names/2.9.6/jackson-module-parameter-names-2.9.6.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-reactor-netty/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-reactor-netty-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/io/projectreactor/netty/reactor-netty/0.8.0.M1/reactor-netty-0.8.0.M1.jar:/Users/bclozel/.m2/repository/io/netty/netty-codec-http/4.1.27.Final/netty-codec-http-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-codec/4.1.27.Final/netty-codec-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-codec-http2/4.1.27.Final/netty-codec-http2-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-handler/4.1.27.Final/netty-handler-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-buffer/4.1.27.Final/netty-buffer-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-transport/4.1.27.Final/netty-transport-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-resolver/4.1.27.Final/netty-resolver-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-handler-proxy/4.1.27.Final/netty-handler-proxy-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-codec-socks/4.1.27.Final/netty-codec-socks-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-transport-native-epoll/4.1.27.Final/netty-transport-native-epoll-4.1.27.Final-linux-x86_64.jar:/Users/bclozel/.m2/repository/io/netty/netty-common/4.1.27.Final/netty-common-4.1.27.Final.jar:/Users/bclozel/.m2/repository/io/netty/netty-transport-native-unix-common/4.1.27.Final/netty-transport-native-unix-common-4.1.27.Final.jar:/Users/bclozel/.m2/repository/org/hibernate/validator/hibernate-validator/6.0.11.Final/hibernate-validator-6.0.11.Final.jar:/Users/bclozel/.m2/repository/javax/validation/validation-api/2.0.1.Final/validation-api-2.0.1.Final.jar:/Users/bclozel/.m2/repository/org/jboss/logging/jboss-logging/3.3.2.Final/jboss-logging-3.3.2.Final.jar:/Users/bclozel/.m2/repository/com/fasterxml/classmate/1.3.4/classmate-1.3.4.jar:/Users/bclozel/.m2/repository/org/springframework/spring-web/5.1.0.RC1/spring-web-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-beans/5.1.0.RC1/spring-beans-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-webflux/5.1.0.RC1/spring-webflux-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/io/projectreactor/reactor-core/3.2.0.M3/reactor-core-3.2.0.M3.jar:/Users/bclozel/.m2/repository/org/reactivestreams/reactive-streams/1.0.2/reactive-streams-1.0.2.jar:/Users/bclozel/.m2/repository/org/synchronoss/cloud/nio-multipart-parser/1.1.0/nio-multipart-parser-1.1.0.jar:/Users/bclozel/.m2/repository/org/slf4j/slf4j-api/1.7.25/slf4j-api-1.7.25.jar:/Users/bclozel/.m2/repository/org/synchronoss/cloud/nio-stream-storage/1.1.3/nio-stream-storage-1.1.3.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-web/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-web-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-tomcat/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-tomcat-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/apache/tomcat/embed/tomcat-embed-core/9.0.10/tomcat-embed-core-9.0.10.jar:/Users/bclozel/.m2/repository/org/apache/tomcat/embed/tomcat-embed-el/9.0.10/tomcat-embed-el-9.0.10.jar:/Users/bclozel/.m2/repository/org/apache/tomcat/embed/tomcat-embed-websocket/9.0.10/tomcat-embed-websocket-9.0.10.jar:/Users/bclozel/.m2/repository/org/springframework/spring-webmvc/5.1.0.RC1/spring-webmvc-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-aop/5.1.0.RC1/spring-aop-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-context/5.1.0.RC1/spring-context-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-expression/5.1.0.RC1/spring-expression-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-starter-actuator/2.1.0.BUILD-SNAPSHOT/spring-boot-starter-actuator-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-actuator-autoconfigure/2.1.0.BUILD-SNAPSHOT/spring-boot-actuator-autoconfigure-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-actuator/2.1.0.BUILD-SNAPSHOT/spring-boot-actuator-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/io/micrometer/micrometer-core/1.0.6/micrometer-core-1.0.6.jar:/Users/bclozel/.m2/repository/org/hdrhistogram/HdrHistogram/2.1.10/HdrHistogram-2.1.10.jar:/Users/bclozel/.m2/repository/org/latencyutils/LatencyUtils/2.0.3/LatencyUtils-2.0.3.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-devtools/2.1.0.BUILD-SNAPSHOT/spring-boot-devtools-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot/2.1.0.BUILD-SNAPSHOT/spring-boot-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/boot/spring-boot-autoconfigure/2.1.0.BUILD-SNAPSHOT/spring-boot-autoconfigure-2.1.0.BUILD-SNAPSHOT.jar:/Users/bclozel/.m2/repository/org/springframework/spring-core/5.1.0.RC1/spring-core-5.1.0.RC1.jar:/Users/bclozel/.m2/repository/org/springframework/spring-jcl/5.1.0.RC1/spring-jcl-5.1.0.RC1.jar com.example.demo.DemoApplication
sun.reflect.ReflectionFactory@1d9b7cce
23:11:04.868 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Included patterns for restart : []
23:11:04.872 [main] DEBUG org.springframework.boot.devtools.settings.DevToolsSettings - Excluded patterns for restart : [/spring-boot-starter-[\w-]+/, /spring-boot/target/classes/, /spring-boot-starter/target/classes/, /spring-boot-devtools/target/classes/, /spring-boot-actuator/target/classes/, /spring-boot-autoconfigure/target/classes/]
23:11:04.872 [main] DEBUG org.springframework.boot.devtools.restart.ChangeableUrls - Matching URLs for reloading : [file:/Users/bclozel/workspace/tmp/demo/target/classes/]
sun.reflect.ReflectionFactory@1d9b7cce

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::  (v2.1.0.BUILD-SNAPSHOT)

2018-07-26 23:11:05.226  INFO 8126 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication on Brians-MacBook-Pro.local with PID 8126 (/Users/bclozel/workspace/tmp/demo/target/classes started by bclozel in /Users/bclozel/workspace/tmp/demo)
2018-07-26 23:11:05.230  INFO 8126 --- [  restartedMain] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2018-07-26 23:11:06.664  INFO 8126 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2018-07-26 23:11:06.681  INFO 8126 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2018-07-26 23:11:06.682  INFO 8126 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet Engine: Apache Tomcat/9.0.10
2018-07-26 23:11:06.699  INFO 8126 --- [  restartedMain] o.a.catalina.core.AprLifecycleListener   : The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [/Users/bclozel/Library/Java/Extensions:/Library/Java/Extensions:/Network/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java:.]
2018-07-26 23:11:06.776  INFO 8126 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2018-07-26 23:11:06.776 DEBUG 8126 --- [  restartedMain] o.s.web.context.ContextLoader            : Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
2018-07-26 23:11:06.776  INFO 8126 --- [  restartedMain] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 1492 ms
2018-07-26 23:11:07.058  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'characterEncodingFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'webMvcMetricsFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'requestContextFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.FilterRegistrationBean   : Mapping filter: 'httpTraceFilter' to: [/*]
2018-07-26 23:11:07.059  INFO 8126 --- [  restartedMain] o.s.b.w.servlet.ServletRegistrationBean  : Servlet dispatcherServlet mapped to [/]
2018-07-26 23:11:07.156 DEBUG 8126 --- [  restartedMain] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/**/favicon.ico] in 'faviconHandlerMapping'
2018-07-26 23:11:07.224 DEBUG 8126 --- [  restartedMain] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1, ResponseBodyAdvice
2018-07-26 23:11:07.268 DEBUG 8126 --- [  restartedMain] s.w.s.m.m.a.RequestMappingHandlerMapping : 5 mappings in 'requestMappingHandlerMapping'
2018-07-26 23:11:07.277 DEBUG 8126 --- [  restartedMain] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
2018-07-26 23:11:07.290 DEBUG 8126 --- [  restartedMain] .m.m.a.ExceptionHandlerExceptionResolver : ControllerAdvice beans: 0 @ExceptionHandler, 1 ResponseBodyAdvice
2018-07-26 23:11:07.311  INFO 8126 --- [  restartedMain] o.s.b.a.w.s.WelcomePageHandlerMapping    : Adding welcome page: class path resource [static/index.html]
2018-07-26 23:11:07.562  INFO 8126 --- [  restartedMain] o.s.b.d.a.OptionalLiveReloadServer       : LiveReload server is running on port 35729
2018-07-26 23:11:07.568  INFO 8126 --- [  restartedMain] o.s.b.a.e.web.EndpointLinksResolver      : Exposing 15 endpoint(s) beneath base path '/actuator'
2018-07-26 23:11:07.648  INFO 8126 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-07-26 23:11:07.653  INFO 8126 --- [  restartedMain] com.example.demo.DemoApplication         : Started DemoApplication in 2.765 seconds (JVM running for 3.603)
2018-07-26 23:11:07.762  INFO 8126 --- [on(2)-127.0.0.1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2018-07-26 23:11:07.763  INFO 8126 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2018-07-26 23:11:07.763 DEBUG 8126 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
2018-07-26 23:11:07.768 DEBUG 8126 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2018-07-26 23:11:07.768  INFO 8126 --- [on(2)-127.0.0.1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 5 ms
2018-07-26 23:11:13.177 DEBUG 8126 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
2018-07-26 23:11:13.183 DEBUG 8126 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/?name=Boot", parameters={masked}
2018-07-26 23:11:13.186 DEBUG 8126 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
2018-07-26 23:11:13.205 DEBUG 8126 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/html', given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
2018-07-26 23:11:13.205 DEBUG 8126 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["Hello, Boot"]
2018-07-26 23:11:13.214 DEBUG 8126 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK
2018-07-26 23:11:15.789 DEBUG 8126 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
2018-07-26 23:11:15.790 DEBUG 8126 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : GET "/", parameters={}
2018-07-26 23:11:15.792 DEBUG 8126 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
2018-07-26 23:11:15.793 DEBUG 8126 --- [nio-8080-exec-2] .w.s.m.m.a.ServletInvocableHandlerMethod : Could not resolve parameter [0] in public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String): Required String parameter 'name' is not present
2018-07-26 23:11:15.795  WARN 8126 --- [nio-8080-exec-2] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.web.bind.MissingServletRequestParameterException: Required String parameter 'name' is not present]
2018-07-26 23:11:15.796 DEBUG 8126 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed 400 BAD_REQUEST
2018-07-26 23:11:15.799 DEBUG 8126 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2018-07-26 23:11:15.805 DEBUG 8126 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-07-26 23:11:15.816 DEBUG 8126 --- [nio-8080-exec-2] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, text/html;q=0.8]
2018-07-26 23:11:15.827 DEBUG 8126 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400
2018-07-26 23:11:18.420 DEBUG 8126 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.status()
2018-07-26 23:11:18.421 DEBUG 8126 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : GET "/status", parameters={}
2018-07-26 23:11:18.423 DEBUG 8126 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.status()
2018-07-26 23:11:18.424  WARN 8126 --- [nio-8080-exec-3] .w.s.m.a.ResponseStatusExceptionResolver : Resolved [org.springframework.web.server.ResponseStatusException: 400 BAD_REQUEST]
2018-07-26 23:11:18.425 DEBUG 8126 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Completed 400 BAD_REQUEST
2018-07-26 23:11:18.425 DEBUG 8126 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2018-07-26 23:11:18.427 DEBUG 8126 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-07-26 23:11:18.437 DEBUG 8126 --- [nio-8080-exec-3] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, text/html;q=0.8]
2018-07-26 23:11:18.437 DEBUG 8126 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 400
2018-07-26 23:11:22.188 DEBUG 8126 --- [nio-8080-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.boom()
2018-07-26 23:11:22.189 DEBUG 8126 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : GET "/boom", parameters={}
2018-07-26 23:11:22.190 DEBUG 8126 --- [nio-8080-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.boom()
2018-07-26 23:11:22.193 DEBUG 8126 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : Failed to complete request: java.lang.IllegalArgumentException: Something illegal
2018-07-26 23:11:22.201 ERROR 8126 --- [nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalArgumentException: Something illegal] with root cause

java.lang.IllegalArgumentException: Something illegal
	at com.example.demo.MvcHomeController.boom(MvcHomeController.java:22) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:207) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:880) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:785) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1041) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:998) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:890) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:875) ~[spring-webmvc-5.1.0.RC1.jar:5.1.0.RC1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:90) ~[spring-boot-actuator-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:112) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:155) ~[spring-boot-actuator-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:123) ~[spring-boot-actuator-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:108) ~[spring-boot-actuator-2.1.0.BUILD-SNAPSHOT.jar:2.1.0.BUILD-SNAPSHOT]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.0.RC1.jar:5.1.0.RC1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:491) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:764) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1388) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.10.jar:9.0.10]
	at java.base/java.lang.Thread.run(Thread.java:844) [na:na]

2018-07-26 23:11:22.203 DEBUG 8126 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2018-07-26 23:11:22.204 DEBUG 8126 --- [nio-8080-exec-4] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-07-26 23:11:22.210 DEBUG 8126 --- [nio-8080-exec-4] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, text/html;q=0.8]
2018-07-26 23:11:22.210 DEBUG 8126 --- [nio-8080-exec-4] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 500
2018-07-26 23:11:25.666 DEBUG 8126 --- [nio-8080-exec-5] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/", "/"]
2018-07-26 23:11:25.667 DEBUG 8126 --- [nio-8080-exec-5] o.s.web.servlet.DispatcherServlet        : GET "/notfound", parameters={}
2018-07-26 23:11:25.668 DEBUG 8126 --- [nio-8080-exec-5] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/", "/"]
2018-07-26 23:11:25.669 DEBUG 8126 --- [nio-8080-exec-5] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
2018-07-26 23:11:25.669 DEBUG 8126 --- [nio-8080-exec-5] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND
2018-07-26 23:11:25.669 DEBUG 8126 --- [nio-8080-exec-5] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2018-07-26 23:11:25.670 DEBUG 8126 --- [nio-8080-exec-5] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-07-26 23:11:25.674 DEBUG 8126 --- [nio-8080-exec-5] o.s.w.s.v.ContentNegotiatingViewResolver : Selected 'text/html' given [text/html, text/html;q=0.8]
2018-07-26 23:11:25.675 DEBUG 8126 --- [nio-8080-exec-5] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404

Possible improvements

• tune down the Tomcat logging for dispatcher servlet registration (see existing logging configuration)
• can we do something about the full exception stacktraces?
• rework the logs written when registering Servlet Filters in Spring Boot (can we regroup all logs into one line?)

[rstoyanchev]

Neat!

What about also org.springframework.http and org.springframework.core.codec? That would eliminate the generic, fallback logging to o.s.w.HttpLogging.

Very minor but this seems to have some but not all changes from this commit yestereday spring-projects/spring-framework@14d0fee. For example the ContextLoader messages are what they were before, while FrameworkServlet ones are current. It's almost like spring-web is a stale snapshot.

The stack trace is coming from Tomcat. Perhaps FrameworkServlet could stop exceptions, or have a property to stop exceptions and set the status to 500. That should still trigger the error dispatch, I hope?

The extra dispatcher servlet init comes from the FrameworkServlet writing via getServletContext().getLog(). I wonder if we really need to log to both places.

[bclozel]

I've just updated the sample logs after configuring org.springframework.http and org.springframework.core.codec for DEBUG. My sample app is using 5.1.0.RC1. After adding a breakpoint in there, it seems debug is not enabled - should I add org.springframework.context.support to the DEBUG list as well?

Logging request details

As you've said, there are now ways to configure whether to log request details (header and body, which might contain sensitive information):

• with Spring MVC, dispatcherServlet.setEnableLoggingRequestDetails(true)
• with Spring WebFlux, on the codecs directly configurer.defaultCodecs().enableLoggingRequestDetails(true) - which applies to both server and WebClient

We should support those as configuration properties (and decide whether we want to enable those by default with devtools).

spring.mvc.log-request-details=true
spring.webflux.log-request-details=true

The obvious solution is a bit strange, because one is server only, and the other one server and client, even if they're doing (almost) the same thing. Also, since the webflux one is done on the codecs, this solution is creating a dependency between CodecsAutoConfiguration and WebFluxProperties, which feels a bit strange.

We could also consider a different solution with another namespace that's about giving insights into the application. I don't know if this really deserve a new namespace, but I'm wondering if more things like this are expected.

spring.insights.web.log-request-details=true

I'm marking this issue for team-attention, especially for that last bit.

[snicoll]

spring.insights.web.log-request-details (note the web namespace) looks better to me than the two separate properties. insights is some name @bclozel and I came up when discussing about the feature. I don't know if it's worth introducing a new "high-level" concept for this but I'd rather have that in a dedicated namespace rather than a few properties here and there.

[rstoyanchev]

This should also make it easier to cover the scenario Spring MVC Controller + WebClient I think.