Marty Pitt opened SPR-15083 and commented
When a Rest controller's @RequestBody params can't be deserialized because of incorrect JSON, the error is lost through the reactive chain.
Specifically, when Jackson throws an exception during deserialization, the exception is lost.
In my specific example, this was a Kotlin class, and I didn't pass a value for a required param.
However, I suspect the same issue would occur with a malformed date, data type mismatch, etc.
A meaningful exception is thrown from Jackson (I see it caught in Jackson2JsonDecoder, line 121:
catch (IOException ex) {
return Flux.error(new CodecException("Error while reading the data", ex));
}
However, when this makes it's way back up to FluxMapFuseable, and into the Reactive land, this somehow gets lost, and the below exception is what we end up with.
It'd be great to see the original exception from Jackson be made available somehow, and - ideally - this result in a 4xx error.
Stack trace below:
java.lang.IllegalStateException: Failed to invoke controller with resolved arguments: [0][type=reactor.core.publisher.FluxOnAssembly][value={ operator : "OnAssembly" }] on method [public reactor.core.publisher.Mono<io.fullyloaded.conductor.plans.Plan> io.fullyloaded.conductor.plans.PlanController.addThing(io.fullyloaded.conductor.plans.Thing2)]
at org.springframework.web.reactive.result.method.InvocableHandlerMethod.lambda$invoke$0(InvocableHandlerMethod.java:112) ~[spring-web-reactive-5.0.0.BUILD-20170101.132107-475.jar:5.0.0.BUILD-SNAPSHOT]
at reactor.core.publisher.MonoThenMap$MonoThenApplyMain.onNext(MonoThenMap.java:98) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:990) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.MonoWhen$MonoWhenCoordinator.signal(MonoWhen.java:231) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.MonoWhen$MonoWhenSubscriber.onNext(MonoWhen.java:275) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:173) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:86) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:68) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxResume$ResumeSubscriber.onNext(FluxResume.java:71) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onNext(FluxOnAssembly.java:316) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:990) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:161) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete(FluxOnAssembly.java:327) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete(FluxOnAssembly.java:327) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:798) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:558) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:531) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.onComplete(FluxOnAssembly.java:327) ~[reactor-core-3.0.4.RELEASE.jar:3.0.4.RELEASE]
at org.springframework.http.server.reactive.AbstractListenerReadPublisher$State.onAllDataRead(AbstractListenerReadPublisher.java:331) ~[spring-web-5.0.0.BUILD-20170101.132107-532.jar:5.0.0.BUILD-SNAPSHOT]
at org.springframework.http.server.reactive.AbstractListenerReadPublisher.onAllDataRead(AbstractListenerReadPublisher.java:86) ~[spring-web-5.0.0.BUILD-20170101.132107-532.jar:5.0.0.BUILD-SNAPSHOT]
at org.springframework.http.server.reactive.ServletServerHttpRequest$RequestBodyPublisher$RequestBodyPublisherReadListener.onAllDataRead(ServletServerHttpRequest.java:250) ~[spring-web-5.0.0.BUILD-20170101.132107-532.jar:5.0.0.BUILD-SNAPSHOT]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:361) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_65]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-8.5.6.jar:8.5.6]
at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_65]
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Assembly trace from producer [reactor.core.publisher.MonoError] :
reactor.core.publisher.Mono.error(Mono.java:274)
org.springframework.web.reactive.result.method.InvocableHandlerMethod.lambda$invoke$0(InvocableHandlerMethod.java:112)
reactor.core.publisher.MonoThenMap$MonoThenApplyMain.onNext(MonoThenMap.java:98)
reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:990)
reactor.core.publisher.MonoWhen$MonoWhenCoordinator.signal(MonoWhen.java:231)
reactor.core.publisher.MonoWhen$MonoWhenSubscriber.onNext(MonoWhen.java:275)
reactor.core.publisher.FluxPeekFuseable$PeekFuseableSubscriber.onNext(FluxPeekFuseable.java:173)
reactor.core.publisher.FluxDefaultIfEmpty$DefaultIfEmptySubscriber.onNext(FluxDefaultIfEmpty.java:86)
reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:68)
reactor.core.publisher.FluxResume$ResumeSubscriber.onNext(FluxResume.java:71)
reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:990)
reactor.core.publisher.MonoSingle$SingleSubscriber.onComplete(MonoSingle.java:161)
reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onComplete(FluxMapFuseable.java:150)
reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:798)
reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:558)
reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:538)
reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:531)
org.springframework.http.server.reactive.AbstractListenerReadPublisher$State.onAllDataRead(AbstractListenerReadPublisher.java:331)
org.springframework.http.server.reactive.AbstractListenerReadPublisher.onAllDataRead(AbstractListenerReadPublisher.java:86)
org.springframework.http.server.reactive.ServletServerHttpRequest$RequestBodyPublisher$RequestBodyPublisherReadListener.onAllDataRead(ServletServerHttpRequest.java:250)
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784)
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
Composition chain until failing Operator :
|_ Mono.error(InvocableHandlerMethod.java:112)
Affects: 5.0 M4
Referenced from: commits https://github.com/spring-projects/spring-boot/commit/e399cf691888f311bbe886ff61703ca54004e0ca
Comment From: spring-projects-issues
Brian Clozel commented
How are you running your application?
If you're using plain Spring Framework, did you activate the "stacktrace mode" option with the following:
Hooks.onOperator(h -> h.operatorStacktrace());
If you're using the experimental boot starter, adding the Spring Boot Devtools dependency should enable that option.
Comment From: spring-projects-issues
Marty Pitt commented
It's a Spring Boot application, and I created it via start.spring.io with the experimental reactive-web.
A bunch of stuff that may help -- let me know if there's any other information I can provide:
- The parent is spring-boot-starter-parent 2.0.0.BUILD-SNAPSHOT
- I have devtools present in the pom
- Adding the Hooks.onOperator() call generated a runtime exception indicating this was already present
- I have a dependency on spring-boot-starter-web-reactive
- I'm using the annotation driver (
@RestController) style of controllers, declaring return types as Mono\, rather than the functional style
Comment From: spring-projects-issues
Sébastien Deleuze commented
Indeed Spring MVC and Spring WebFlux behavior seems to be different here, and that makes debugging painful.
In addition to the lack of stacktrace, the JSON error output lack of useful information:
Spring MVC
{
"error": "Bad Request",
"message": "JSON parse error: Instantiation of [simple type, class com.example.demojpakotlin.Foo] value failed for JSON property name due to missing (therefore NULL) value for creator parameter name which is a non-nullable type; nested exception is com.fasterxml.jackson.module.kotlin.MissingKotlinParameterException: Instantiation of [simple type, class com.example.demojpakotlin.Foo] value failed for JSON property name due to missing (therefore NULL) value for creator parameter name which is a non-nullable type\n at [Source: (PushbackInputStream); line: 1, column: 19] (through reference chain: com.example.demojpakotlin.Foo[\"name\"])",
"path": "/",
"status": 400,
"timestamp": "2018-01-26T15:43:54.885+0000"
}
Spring WebFlux
{
"error": "Bad Request",
"message": "Failed to read HTTP message",
"path": "/",
"status": 400,
"timestamp": "2018-01-26T15:44:38.645+0000"
}
Comment From: spring-projects-issues
Sébastien Deleuze commented
With this commit (not merged yet) WebFlux provides the detailed message of the original exception like MVC does in the HTTP response body.
Printing the exception in the logs seems to be more on Spring Boot side via DefaultErrorWebExceptionHandler#logError which currently prints only 5xx error with an error level. I am wondering if it should also print 4xx error with an warn level in order to be consistent with what happens on MVC side and make it easier to find the root cause of such application error which is currently pretty hard.
Any thoughts Rossen Stoyanchev Brian Clozel?
Comment From: spring-projects-issues
Sébastien Deleuze commented
Additional info : with Spring MVC, logging is performed by DefaultHandlerExceptionResolver#handleHttpMessageNotReadable and exception type is HttpMessageNotReadableException.
With WebFlux, the exception is a ServerWebInputException but is currently not logged because status code is 4xx not 5xx.
Comment From: spring-projects-issues
Sébastien Deleuze commented
I have draft WebFlux and Boot commits in order to discuss on a more concrete proposal.
Comment From: spring-projects-issues
Sébastien Deleuze commented
Pull request submitted for review by Rossen Stoyanchev and Brian Clozel.
Comment From: spring-projects-issues
Sébastien Deleuze commented
Merged with this commit (wrong issue mentioned in the commit log :-(, sorry for that) as a general improvement of WebFlux exception logging : 400 errors are now logged, no stack trace only the message for ResponseStatusException and the request method and uri are now logged for more contextual error messages.