Unhandled exceptions are not logged with WebFlux

[sdeleuze]

Consider this simple controller:

@RestController
public class FooController {
	@GetMapping("/")
	public String foo() {
		throw new RuntimeException("foo");
	}
}

With Spring Boot 2.1.2 and Spring MVC:

2019-01-23 12:13:22.249 ERROR 7563 --- [nio-8080-exec-1] 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.RuntimeException: foo] with root cause

java.lang.RuntimeException: foo
	at com.example.demologgingerrors.FooController.foo(FooController.java:11) ~[classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_181]
	...

With Spring Boot 2.1.2 and Spring WebFlux, nothing is logged and even if I configure logging.level.org.springframework.boot.autoconfigure.web.reactive.error.DefaultErrorWebExceptionHandler=debug I don't have the stacktrace, juste the exception class and the message. Same behavior with Mono.error(new RuntimeException("foo")) or when using the functional WebFlux API.

Maybe something missing in AbstractErrorWebExceptionHandler as suggested by @bclozel. I think this is a pretty serious issue.

[bclozel]

This is now fixed, and you'll now get the exception logged at ERROR level.

In Spring WebFlux, we've got access to the logPrefix for each server exchange and this information is being logged:

2019-02-08 14:21:15.507 ERROR 7103 --- [ctor-http-nio-2] a.w.r.e.AbstractErrorWebExceptionHandler : [172cdc16] 500 Server Error for HTTP GET "/"

java.lang.RuntimeException: foo
	at com.example.demo.SomeController.foo(SomeController.java:14) ~[classes/:na]
	...

@sdeleuze Do you think it could be interesting to add that information to the ErrorAttributes by default and use it as well on the whitelabel error page like:

Whitelabel Error Page
This application has no configured error view, so you are seeing this as a fallback.

[172cdc16] Fri Feb 08 14:21:15 CET 2019
There was an unexpected error (type=Internal Server Error, status=500).
foo

This would help developers get the relevant lines in the logs.

[sdeleuze]

Thanks @bclozel! Yes, I think it could be super useful for developers indeed. Is it possible to add it?

[mbreevoort]

Why is this fix where the error is logged cba6079#diff-f5a9bc6f98f7ae6a7faa9e2a41e332b2 removed in 2.1.4?
Is this correct or because of an incorrect merge @sdeleuze or @wilkinsona ?

[wilkinsona]

As far as I can tell, the fix hasn't been removed in 2.1.4. For example, here are the four private methods in 2.1.4.RELEASE (4840503 is the commit for 2.1.4) that were added in cba6079:

spring-boot/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/AbstractErrorWebExceptionHandler.java

Lines 287 to 297 in 4840503

	private void logError(ServerRequest request, ServerResponse response,
	Throwable throwable) {
	if (logger.isDebugEnabled()) {
	logger.debug(
	request.exchange().getLogPrefix() + formatError(throwable, request));
	}
	if (response.statusCode().equals(HttpStatus.INTERNAL_SERVER_ERROR)) {
	logger.error(request.exchange().getLogPrefix() + "500 Server Error for "
	+ formatRequest(request), throwable);
	}
	}

[mbreevoort]

Thanks @wilkinsona for the quick reply. Ah ok it's moved to AbstractErrorWebExceptionHandler and a private function now. I implemented my own logError because the implementation in 2.1.2 only logged at debug level and there where no stacktraces. The current implementation logs errors with stacktraces, thanks.