From cba6079b7b85001f19f6e0e5b7fda4a24e05c34a Mon Sep 17 00:00:00 2001 From: Brian Clozel Date: Fri, 8 Feb 2019 12:25:05 +0100 Subject: [PATCH] Log unhandled server exceptions in WebFlux Prior to this commit, errors unhandled by custom `WebExceptionHandler` and resulting in an HTTP 500 status would not be logged at ERROR level, giving no information to developers about the actual exception. This commit ensures that such exceptions are logged at the ERROR level with their exception. By the time the exception hits the `DefaultErrorWebExceptionHandler`, if the response is already committed or if the exception is due to a client disconnecting, the error is delegated to Framework support as Spring Boot won't be able to render an error page as expected. Fixes gh-15769 --- .../AbstractErrorWebExceptionHandler.java | 55 ++++++++++++++++++- .../DefaultErrorWebExceptionHandler.java | 31 +---------- ...orWebExceptionHandlerIntegrationTests.java | 15 ++++- 3 files changed, 70 insertions(+), 31 deletions(-) diff --git a/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/AbstractErrorWebExceptionHandler.java b/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/AbstractErrorWebExceptionHandler.java index 495eafecba..bf30331693 100644 --- a/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/AbstractErrorWebExceptionHandler.java +++ b/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/AbstractErrorWebExceptionHandler.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2018 the original author or authors. + * Copyright 2012-2019 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -16,11 +16,15 @@ package org.springframework.boot.autoconfigure.web.reactive.error; +import java.util.Arrays; import java.util.Collections; import java.util.Date; +import java.util.HashSet; import java.util.List; import java.util.Map; +import java.util.Set; +import org.apache.commons.logging.Log; import reactor.core.publisher.Mono; import org.springframework.beans.factory.InitializingBean; @@ -29,11 +33,15 @@ import org.springframework.boot.autoconfigure.web.ResourceProperties; import org.springframework.boot.web.reactive.error.ErrorAttributes; import org.springframework.boot.web.reactive.error.ErrorWebExceptionHandler; import org.springframework.context.ApplicationContext; +import org.springframework.core.NestedExceptionUtils; import org.springframework.core.io.Resource; +import org.springframework.http.HttpLogging; +import org.springframework.http.HttpStatus; import org.springframework.http.codec.HttpMessageReader; import org.springframework.http.codec.HttpMessageWriter; import org.springframework.util.Assert; import org.springframework.util.CollectionUtils; +import org.springframework.util.StringUtils; import org.springframework.web.reactive.function.BodyInserters; import org.springframework.web.reactive.function.server.RouterFunction; import org.springframework.web.reactive.function.server.ServerRequest; @@ -52,6 +60,15 @@ import org.springframework.web.util.HtmlUtils; public abstract class AbstractErrorWebExceptionHandler implements ErrorWebExceptionHandler, InitializingBean { + /** + * Currently duplicated from Spring WebFlux HttpWebHandlerAdapter. + */ + private static final Set DISCONNECTED_CLIENT_EXCEPTIONS = new HashSet<>( + Arrays.asList("ClientAbortException", "EOFException", "EofException")); + + private static final Log logger = HttpLogging + .forLogName(AbstractErrorWebExceptionHandler.class); + private final ApplicationContext applicationContext; private final ErrorAttributes errorAttributes; @@ -236,7 +253,8 @@ public abstract class AbstractErrorWebExceptionHandler @Override public Mono handle(ServerWebExchange exchange, Throwable throwable) { - if (exchange.getResponse().isCommitted()) { + if (exchange.getResponse().isCommitted() + || isDisconnectedClientError(throwable)) { return Mono.error(throwable); } this.errorAttributes.storeErrorInformation(throwable, exchange); @@ -244,9 +262,42 @@ public abstract class AbstractErrorWebExceptionHandler return getRoutingFunction(this.errorAttributes).route(request) .switchIfEmpty(Mono.error(throwable)) .flatMap((handler) -> handler.handle(request)) + .doOnNext((response) -> logError(request, response, throwable)) .flatMap((response) -> write(exchange, response)); } + private boolean isDisconnectedClientError(Throwable ex) { + String message = NestedExceptionUtils.getMostSpecificCause(ex).getMessage(); + message = (message != null) ? message.toLowerCase() : ""; + String className = ex.getClass().getSimpleName(); + return (message.contains("broken pipe") + || DISCONNECTED_CLIENT_EXCEPTIONS.contains(className)); + } + + 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); + } + } + + private String formatError(Throwable ex, ServerRequest request) { + String reason = ex.getClass().getSimpleName() + ": " + ex.getMessage(); + return "Resolved [" + reason + "] for HTTP " + request.methodName() + " " + + request.path(); + } + + private String formatRequest(ServerRequest request) { + String rawQuery = request.uri().getRawQuery(); + String query = StringUtils.hasText(rawQuery) ? "?" + rawQuery : ""; + return "HTTP " + request.methodName() + " \"" + request.path() + query + "\""; + } + private Mono write(ServerWebExchange exchange, ServerResponse response) { // force content-type since writeTo won't overwrite response header values diff --git a/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandler.java b/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandler.java index 1bc722fbfe..2bb4946cbf 100644 --- a/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandler.java +++ b/spring-boot-project/spring-boot-autoconfigure/src/main/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandler.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2018 the original author or authors. + * Copyright 2012-2019 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -21,7 +21,6 @@ import java.util.EnumMap; import java.util.List; import java.util.Map; -import org.apache.commons.logging.Log; import reactor.core.publisher.Flux; import reactor.core.publisher.Mono; @@ -29,7 +28,6 @@ import org.springframework.boot.autoconfigure.web.ErrorProperties; import org.springframework.boot.autoconfigure.web.ResourceProperties; import org.springframework.boot.web.reactive.error.ErrorAttributes; import org.springframework.context.ApplicationContext; -import org.springframework.http.HttpLogging; import org.springframework.http.HttpStatus; import org.springframework.http.InvalidMediaTypeException; import org.springframework.http.MediaType; @@ -77,9 +75,6 @@ public class DefaultErrorWebExceptionHandler extends AbstractErrorWebExceptionHa private static final Map SERIES_VIEWS; - private static final Log logger = HttpLogging - .forLogName(DefaultErrorWebExceptionHandler.class); - static { Map views = new EnumMap<>(HttpStatus.Series.class); views.put(HttpStatus.Series.CLIENT_ERROR, "4xx"); @@ -128,7 +123,7 @@ public class DefaultErrorWebExceptionHandler extends AbstractErrorWebExceptionHa .switchIfEmpty(this.errorProperties.getWhitelabel().isEnabled() ? renderDefaultErrorView(responseBody, error) : Mono.error(getError(request))) - .next().doOnNext((response) -> logError(request, errorStatus)); + .next(); } /** @@ -142,8 +137,7 @@ public class DefaultErrorWebExceptionHandler extends AbstractErrorWebExceptionHa HttpStatus errorStatus = getHttpStatus(error); return ServerResponse.status(getHttpStatus(error)) .contentType(MediaType.APPLICATION_JSON_UTF8) - .body(BodyInserters.fromObject(error)) - .doOnNext((resp) -> logError(request, errorStatus)); + .body(BodyInserters.fromObject(error)); } /** @@ -196,23 +190,4 @@ public class DefaultErrorWebExceptionHandler extends AbstractErrorWebExceptionHa }; } - /** - * Log the original exception if handling it results in a Server Error or a Bad - * Request (Client Error with 400 status code) one. - * @param request the source request - * @param errorStatus the HTTP error status - */ - protected void logError(ServerRequest request, HttpStatus errorStatus) { - Throwable ex = getError(request); - if (logger.isDebugEnabled()) { - logger.debug(request.exchange().getLogPrefix() + formatError(ex, request)); - } - } - - private String formatError(Throwable ex, ServerRequest request) { - String reason = ex.getClass().getSimpleName() + ": " + ex.getMessage(); - return "Resolved [" + reason + "] for HTTP " + request.methodName() + " " - + request.path(); - } - } diff --git a/spring-boot-project/spring-boot-autoconfigure/src/test/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandlerIntegrationTests.java b/spring-boot-project/spring-boot-autoconfigure/src/test/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandlerIntegrationTests.java index 67b91eb4b7..450410cd6b 100644 --- a/spring-boot-project/spring-boot-autoconfigure/src/test/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandlerIntegrationTests.java +++ b/spring-boot-project/spring-boot-autoconfigure/src/test/java/org/springframework/boot/autoconfigure/web/reactive/error/DefaultErrorWebExceptionHandlerIntegrationTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2018 the original author or authors. + * Copyright 2012-2019 the original author or authors. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -18,6 +18,8 @@ package org.springframework.boot.autoconfigure.web.reactive.error; import javax.validation.Valid; +import org.hamcrest.Matchers; +import org.junit.Rule; import org.junit.Test; import reactor.core.publisher.Mono; @@ -28,6 +30,7 @@ import org.springframework.boot.autoconfigure.web.reactive.HttpHandlerAutoConfig import org.springframework.boot.autoconfigure.web.reactive.ReactiveWebServerFactoryAutoConfiguration; import org.springframework.boot.autoconfigure.web.reactive.WebFluxAutoConfiguration; import org.springframework.boot.test.context.runner.ReactiveWebApplicationContextRunner; +import org.springframework.boot.testsupport.rule.OutputCapture; import org.springframework.context.annotation.Configuration; import org.springframework.http.HttpStatus; import org.springframework.http.MediaType; @@ -42,6 +45,7 @@ import org.springframework.web.server.ServerWebExchange; import static org.assertj.core.api.Assertions.assertThat; import static org.assertj.core.api.Assertions.assertThatExceptionOfType; +import static org.hamcrest.Matchers.containsString; /** * Integration tests for {@link DefaultErrorWebExceptionHandler} @@ -50,6 +54,9 @@ import static org.assertj.core.api.Assertions.assertThatExceptionOfType; */ public class DefaultErrorWebExceptionHandlerIntegrationTests { + @Rule + public OutputCapture outputCapture = new OutputCapture(); + private ReactiveWebApplicationContextRunner contextRunner = new ReactiveWebApplicationContextRunner() .withConfiguration(AutoConfigurations.of( ReactiveWebServerFactoryAutoConfiguration.class, @@ -73,6 +80,9 @@ public class DefaultErrorWebExceptionHandlerIntegrationTests { .jsonPath("path").isEqualTo(("/")).jsonPath("message") .isEqualTo("Expected!").jsonPath("exception").doesNotExist() .jsonPath("trace").doesNotExist(); + this.outputCapture.expect(Matchers.allOf( + containsString("500 Server Error for HTTP GET \"/\""), + containsString("java.lang.IllegalStateException: Expected!"))); }); } @@ -98,6 +108,9 @@ public class DefaultErrorWebExceptionHandlerIntegrationTests { .expectHeader().contentType(MediaType.TEXT_HTML) .expectBody(String.class).returnResult().getResponseBody(); assertThat(body).contains("status: 500").contains("message: Expected!"); + this.outputCapture.expect(Matchers.allOf( + containsString("500 Server Error for HTTP GET \"/\""), + containsString("java.lang.IllegalStateException: Expected!"))); }); }