]> source.dussan.org Git - sonarqube.git/commitdiff
SONAR-10154 Log debug when HTTP response has been partially streamed
authorTeryk Bellahsene <teryk.bellahsene@sonarsource.com>
Thu, 4 Jan 2018 14:49:49 +0000 (15:49 +0100)
committerTeryk Bellahsene <teryk@users.noreply.github.com>
Mon, 8 Jan 2018 17:54:38 +0000 (18:54 +0100)
server/sonar-server/src/main/java/org/sonar/server/ws/WebServiceEngine.java
server/sonar-server/src/test/java/org/sonar/server/ws/TestRequest.java
server/sonar-server/src/test/java/org/sonar/server/ws/WebServiceEngineTest.java

index d4ad4d5415dac96bcce941dde067f7bfa5daee82..a4be25f44ee293e8ac4ecac6d4a4109619688929 100644 (file)
@@ -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<String> errors) {
+  private static void sendErrors(Request request, Response response, Exception exception, int status, List<String> 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<String> errorMessages) {
     if (errorMessages.isEmpty()) {
       return;
index ce180fdd069ba23dea74311f10e42a61cf515631..49fd109656725155d7cc393407999f261c11bc67 100644 (file)
@@ -152,4 +152,9 @@ public class TestRequest extends ValidatingRequest {
   public <T extends GeneratedMessage> T executeProtobuf(Class<T> protobufClass) {
     return setMediaType(PROTOBUF).execute().getInputObject(protobufClass);
   }
+
+  @Override
+  public String toString() {
+    return path;
+  }
 }
index 5a3093cd26e1e0b96e4a4a6b497e39bc4a9f394d..bff85707dc7aa62e6b0a3f6af1fa64f0ef8229bb 100644 (file)
@@ -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"));
   }
 }