From: Teryk Bellahsene Date: Thu, 4 Jan 2018 14:49:49 +0000 (+0100) Subject: SONAR-10154 Log debug when HTTP response has been partially streamed X-Git-Tag: 7.0-RC1~53 X-Git-Url: https://source.dussan.org/?a=commitdiff_plain;h=4a08bd82b4ad2802cd38a1d352e8b7137773ed34;p=sonarqube.git SONAR-10154 Log debug when HTTP response has been partially streamed --- diff --git a/server/sonar-server/src/main/java/org/sonar/server/ws/WebServiceEngine.java b/server/sonar-server/src/main/java/org/sonar/server/ws/WebServiceEngine.java index d4ad4d5415d..a4be25f44ee 100644 --- a/server/sonar-server/src/main/java/org/sonar/server/ws/WebServiceEngine.java +++ b/server/sonar-server/src/main/java/org/sonar/server/ws/WebServiceEngine.java @@ -26,6 +26,7 @@ import java.util.List; import java.util.Locale; import javax.annotation.CheckForNull; import javax.annotation.Nullable; +import org.apache.catalina.connector.ClientAbortException; import org.picocontainer.Startable; import org.sonar.api.server.ServerSide; import org.sonar.api.server.ws.LocalConnector; @@ -102,22 +103,13 @@ public class WebServiceEngine implements LocalConnector, Startable { verifyRequest(action, request); action.handler().handle(request, response); } catch (IllegalArgumentException e) { - sendErrors(response, 400, singletonList(e.getMessage())); + sendErrors(request, response, e, 400, singletonList(e.getMessage())); } catch (BadRequestException e) { - sendErrors(response, 400, e.errors()); + sendErrors(request, response, e, 400, e.errors()); } catch (ServerException e) { - sendErrors(response, e.httpCode(), singletonList(e.getMessage())); + sendErrors(request, response, e, e.httpCode(), singletonList(e.getMessage())); } catch (Exception e) { - Response.Stream stream = response.stream(); - if (stream instanceof ServletResponse.ServletStream && ((ServletResponse.ServletStream) stream).response().isCommitted()) { - // Request has been aborted by the client, nothing can been done as Tomcat has committed the response - LOGGER.debug("Request {} has been aborted by client, error is '{}'", request, e.getMessage()); - return; - } - LOGGER.error("Fail to process request " + request, e); - // Sending exception message into response is a vulnerability. Error must be - // displayed only in logs. - sendErrors(response, 500, singletonList("An error has occurred. Please contact your administrator")); + sendErrors(request, response, e, 500, singletonList("An error has occurred. Please contact your administrator")); } } @@ -129,18 +121,37 @@ public class WebServiceEngine implements LocalConnector, Startable { return controller == null ? null : controller.action(actionKey); } - private static void sendErrors(Response response, int status, List errors) { + private static void sendErrors(Request request, Response response, Exception exception, int status, List errors) { + if (isRequestAbortedByClient(exception)) { + // do not pollute logs. We can't do anything -> use DEBUG level + // see org.sonar.server.ws.ServletResponse#output() + LOGGER.debug(String.format("Request %s has been aborted by client", request), exception); + if (!isResponseCommitted(response)) { + // can be useful for access.log + response.stream().setStatus(299); + } + return; + } + + if (status == 500) { + // Sending exception message into response is a vulnerability. Error must be + // displayed only in logs. + LOGGER.error("Fail to process request " + request, exception); + } + Response.Stream stream = response.stream(); + if (isResponseCommitted(response)) { + // status can't be changed + LOGGER.debug(String.format("Request %s failed during response streaming", request), exception); + return; + } + + // response is not committed, status and content can be changed to return the error if (stream instanceof ServletResponse.ServletStream) { - if (((ServletResponse.ServletStream) stream).response().isCommitted()) { - // streaming of response. It's no more possible to clear and reformat the response - return; - } ((ServletResponse.ServletStream) stream).reset(); } stream.setStatus(status); stream.setMediaType(MediaTypes.JSON); - try (JsonWriter json = JsonWriter.of(new OutputStreamWriter(stream.output(), StandardCharsets.UTF_8))) { json.beginObject(); writeErrors(json, errors); @@ -151,6 +162,16 @@ public class WebServiceEngine implements LocalConnector, Startable { } } + private static boolean isRequestAbortedByClient(Exception exception) { + return Throwables.getCausalChain(exception).stream().anyMatch(t -> t instanceof ClientAbortException); + } + + private static boolean isResponseCommitted(Response response) { + Response.Stream stream = response.stream(); + // Request has been aborted by the client or the response was partially streamed, nothing can been done as Tomcat has committed the response + return stream instanceof ServletResponse.ServletStream && ((ServletResponse.ServletStream) stream).response().isCommitted(); + } + public static void writeErrors(JsonWriter json, List errorMessages) { if (errorMessages.isEmpty()) { return; diff --git a/server/sonar-server/src/test/java/org/sonar/server/ws/TestRequest.java b/server/sonar-server/src/test/java/org/sonar/server/ws/TestRequest.java index ce180fdd069..49fd1096567 100644 --- a/server/sonar-server/src/test/java/org/sonar/server/ws/TestRequest.java +++ b/server/sonar-server/src/test/java/org/sonar/server/ws/TestRequest.java @@ -152,4 +152,9 @@ public class TestRequest extends ValidatingRequest { public T executeProtobuf(Class protobufClass) { return setMediaType(PROTOBUF).execute().getInputObject(protobufClass); } + + @Override + public String toString() { + return path; + } } diff --git a/server/sonar-server/src/test/java/org/sonar/server/ws/WebServiceEngineTest.java b/server/sonar-server/src/test/java/org/sonar/server/ws/WebServiceEngineTest.java index 5a3093cd26e..bff85707dc7 100644 --- a/server/sonar-server/src/test/java/org/sonar/server/ws/WebServiceEngineTest.java +++ b/server/sonar-server/src/test/java/org/sonar/server/ws/WebServiceEngineTest.java @@ -30,6 +30,8 @@ import org.junit.Before; import org.junit.Rule; import org.junit.Test; import org.junit.rules.ExpectedException; +import org.mockito.Mockito; +import org.sonar.api.server.ws.Request; import org.sonar.api.server.ws.Response; import org.sonar.api.server.ws.WebService; import org.sonar.api.server.ws.internal.ValidatingRequest; @@ -38,8 +40,12 @@ import org.sonar.api.utils.log.LoggerLevel; import org.sonar.server.exceptions.BadRequestException; import org.sonarqube.ws.MediaTypes; +import static java.nio.charset.StandardCharsets.UTF_8; import static org.assertj.core.api.Assertions.assertThat; +import static org.mockito.Matchers.anyInt; import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.never; +import static org.mockito.Mockito.verify; import static org.mockito.Mockito.when; public class WebServiceEngineTest { @@ -69,30 +75,33 @@ public class WebServiceEngineTest { } @Test - public void execute_request() { - ValidatingRequest request = new TestRequest().setMethod("GET").setPath("/api/system/health"); - DumbResponse response = new DumbResponse(); - underTest.execute(request, response); + public void ws_returns_successful_response() { + ValidatingRequest request = new TestRequest().setPath("/api/ping"); - assertThat(response.stream().outputAsString()).isEqualTo("good"); + DumbResponse response = run(request, new PingWs()); + + assertThat(response.stream().outputAsString()).isEqualTo("pong"); + assertThat(response.stream().status()).isEqualTo(200); } @Test - public void execute_request_when_path_does_not_begin_with_slash() { - ValidatingRequest request = new TestRequest().setMethod("GET").setPath("/api/system/health"); - DumbResponse response = new DumbResponse(); - underTest.execute(request, response); + public void accept_path_that_does_not_start_with_slash() { + ValidatingRequest request = new TestRequest().setPath("api/ping"); + + DumbResponse response = run(request, new PingWs()); - assertThat(response.stream().outputAsString()).isEqualTo("good"); + assertThat(response.stream().outputAsString()).isEqualTo("pong"); + assertThat(response.stream().status()).isEqualTo(200); } @Test - public void execute_request_with_action_suffix() { - ValidatingRequest request = new TestRequest().setMethod("GET").setPath("/api/system/health"); - DumbResponse response = new DumbResponse(); - underTest.execute(request, response); + public void request_path_can_contain_valid_media_type() { + ValidatingRequest request = new TestRequest().setPath("api/ping.json"); - assertThat(response.stream().outputAsString()).isEqualTo("good"); + DumbResponse response = run(request, new PingWs()); + + assertThat(response.stream().outputAsString()).isEqualTo("pong"); + assertThat(response.stream().status()).isEqualTo(200); } @Test @@ -293,7 +302,7 @@ public class WebServiceEngineTest { } @Test - public void does_not_fail_to_render_error_message_having_percent() { + public void return_error_message_containing_character_percent() { ValidatingRequest request = new TestRequest().setMethod("GET").setPath("/api/system/error_message_having_percent"); DumbResponse response = new DumbResponse(); @@ -305,7 +314,7 @@ public class WebServiceEngineTest { } @Test - public void should_handle_headers() { + public void send_response_headers() { DumbResponse response = new DumbResponse(); String name = "Content-Disposition"; String value = "attachment; filename=sonarqube.zip"; @@ -315,17 +324,82 @@ public class WebServiceEngineTest { } @Test - public void does_not_fail_when_request_is_aborted_and_response_is_committed() throws Exception { - ValidatingRequest request = new TestRequest().setMethod("GET").setPath("/api/system/fail_with_client_abort_exception"); - Response response = mock(Response.class); - ServletResponse.ServletStream servletStream = mock(ServletResponse.ServletStream.class); + public void support_aborted_request_when_response_is_already_committed() { + ValidatingRequest request = new TestRequest().setPath("/api/system/fail_with_client_abort_exception"); + Response response = mockServletResponse(true); + + underTest.execute(request, response); + + // response is committed (status is already sent), so status can't be changed + verify(response.stream(), never()).setStatus(anyInt()); + + assertThat(logTester.logs(LoggerLevel.DEBUG)).contains("Request /api/system/fail_with_client_abort_exception has been aborted by client"); + } + + @Test + public void support_aborted_request_when_response_is_not_committed() { + ValidatingRequest request = new TestRequest().setPath("/api/system/fail_with_client_abort_exception"); + Response response = mockServletResponse(false); + + underTest.execute(request, response); + + verify(response.stream()).setStatus(299); + assertThat(logTester.logs(LoggerLevel.DEBUG)).contains("Request /api/system/fail_with_client_abort_exception has been aborted by client"); + } + + @Test + public void internal_error_when_response_is_already_committed() { + ValidatingRequest request = new TestRequest().setPath("/api/system/fail"); + Response response = mockServletResponse(true); + + underTest.execute(request, response); + + // response is committed (status is already sent), so status can't be changed + verify(response.stream(), never()).setStatus(anyInt()); + assertThat(logTester.logs(LoggerLevel.ERROR)).contains("Fail to process request /api/system/fail"); + } + + @Test + public void internal_error_when_response_is_not_committed() { + ValidatingRequest request = new TestRequest().setPath("/api/system/fail"); + Response response = mockServletResponse(false); + + underTest.execute(request, response); + + verify(response.stream()).setStatus(500); + assertThat(logTester.logs(LoggerLevel.ERROR)).contains("Fail to process request /api/system/fail"); + } + + private static DumbResponse run(Request request, WebService... webServices) { + WebServiceEngine engine = new WebServiceEngine(webServices); + engine.start(); + try { + DumbResponse response = new DumbResponse(); + engine.execute(request, response); + return response; + } finally { + engine.stop(); + } + } + + private static Response mockServletResponse(boolean committed) { + Response response = mock(Response.class, Mockito.RETURNS_DEEP_STUBS); + ServletResponse.ServletStream servletStream = mock(ServletResponse.ServletStream.class, Mockito.RETURNS_DEEP_STUBS); when(response.stream()).thenReturn(servletStream); - HttpServletResponse httpServletResponse = mock(HttpServletResponse.class); - when(httpServletResponse.isCommitted()).thenReturn(true); + HttpServletResponse httpServletResponse = mock(HttpServletResponse.class, Mockito.RETURNS_DEEP_STUBS); + when(httpServletResponse.isCommitted()).thenReturn(committed); when(servletStream.response()).thenReturn(httpServletResponse); - underTest.execute(request, response); + return response; + } - assertThat(logTester.logs(LoggerLevel.DEBUG)).isNotEmpty(); + private static class PingWs implements WebService { + @Override + public void define(Context context) { + NewController newController = context.createController("api"); + createNewDefaultAction(newController, "ping") + .setHandler((request, response) -> response.stream().output().write("pong".getBytes(UTF_8))); + newController.done(); + } } static class SystemWs implements WebService { @@ -399,6 +473,7 @@ public class WebServiceEngineTest { String param = request.param("required-parameter"); }); + // simulate a client abort createNewDefaultAction(newController, "fail_with_client_abort_exception") .setHandler((request, response) -> { throw new IllegalStateException("fail!", new ClientAbortException()); @@ -407,12 +482,13 @@ public class WebServiceEngineTest { newController.done(); } - private NewAction createNewDefaultAction(NewController controller, String key) { - return controller - .createAction(key) - .setDescription("Dummy Description") - .setSince("5.3") - .setResponseExample(getClass().getResource("web-service-engine-test.txt")); - } + } + + private static WebService.NewAction createNewDefaultAction(WebService.NewController controller, String key) { + return controller + .createAction(key) + .setDescription("Dummy Description") + .setSince("5.3") + .setResponseExample(WebServiceEngineTest.class.getResource("web-service-engine-test.txt")); } }