diff --git a/server/src/main/java/com/defold/extender/RequestErrorAdvice.java b/server/src/main/java/com/defold/extender/RequestErrorAdvice.java new file mode 100644 index 00000000..d6e898cb --- /dev/null +++ b/server/src/main/java/com/defold/extender/RequestErrorAdvice.java @@ -0,0 +1,87 @@ +package com.defold.extender; + +import java.util.Collections; +import java.util.IdentityHashMap; +import java.util.Set; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.springframework.beans.factory.annotation.Value; +import org.springframework.http.HttpHeaders; +import org.springframework.http.HttpStatus; +import org.springframework.http.MediaType; +import org.springframework.http.ResponseEntity; +import org.springframework.web.bind.annotation.ExceptionHandler; +import org.springframework.web.bind.annotation.RestControllerAdvice; +import org.springframework.web.multipart.MaxUploadSizeExceededException; +import org.springframework.web.multipart.MultipartException; + +/** + * Handles uploads that fail while Jetty parses the multipart body. Parsing happens in + * DispatcherServlet.checkMultipart(), i.e. before the request is mapped to a controller method, so + * the @ExceptionHandler methods inside {@link ExtenderController} are never consulted for these + * failures - the request would otherwise end up in Spring's default /error handling, which + * answers with a bare "400 Bad Request" and logs nothing (see defold/extender#590). + */ +@RestControllerAdvice +public class RequestErrorAdvice { + + private static final Logger LOGGER = LoggerFactory.getLogger(RequestErrorAdvice.class); + + // Matches Jetty's message for the part limit: Form with too many keys [1043 > 1000] + private static final Pattern TOO_MANY_PARTS_RE = Pattern.compile("too many keys \\[(\\d+) > (\\d+)]"); + + private final String maxFileSize; + private final String maxRequestSize; + + public RequestErrorAdvice(@Value("${spring.servlet.multipart.max-file-size}") String maxFileSize, + @Value("${spring.servlet.multipart.max-request-size}") String maxRequestSize) { + this.maxFileSize = maxFileSize; + this.maxRequestSize = maxRequestSize; + } + + @ExceptionHandler(MultipartException.class) + public ResponseEntity handleMultipartException(MultipartException ex) { + final Matcher tooManyParts = findTooManyParts(ex); + if (tooManyParts != null) { + final String message = String.format( + "The build request contains too many files (%s, the limit is %s). Reduce the number of files in the project extensions, or update the editor to a version that uploads the sources as a single archive.", + tooManyParts.group(1), tooManyParts.group(2)); + LOGGER.warn(message); + return textResponse(HttpStatus.PAYLOAD_TOO_LARGE, message); + } + + if (ex instanceof MaxUploadSizeExceededException) { + // Spring raises this for both limits without saying which one was hit. + final String message = String.format("The build request is too large. Max allowed size is %s per file and %s per request.", + maxFileSize, maxRequestSize); + LOGGER.warn(message); + return textResponse(HttpStatus.PAYLOAD_TOO_LARGE, message); + } + + final String message = "The build request is not a valid multipart request and could not be read by the server."; + LOGGER.warn(message, ex); + return textResponse(HttpStatus.BAD_REQUEST, message); + } + + private static Matcher findTooManyParts(Throwable ex) { + final Set seen = Collections.newSetFromMap(new IdentityHashMap<>()); + for (Throwable cause = ex; cause != null && seen.add(cause); cause = cause.getCause()) { + if (cause.getMessage() != null) { + final Matcher matcher = TOO_MANY_PARTS_RE.matcher(cause.getMessage()); + if (matcher.find()) { + return matcher; + } + } + } + return null; + } + + private static ResponseEntity textResponse(HttpStatus status, String message) { + HttpHeaders headers = new HttpHeaders(); + headers.setContentType(MediaType.TEXT_PLAIN); + return new ResponseEntity<>(message, headers, status); + } +} diff --git a/server/src/main/java/com/defold/extender/jetty/ExtenderJettyErrorHandler.java b/server/src/main/java/com/defold/extender/jetty/ExtenderJettyErrorHandler.java new file mode 100644 index 00000000..1cabfbe1 --- /dev/null +++ b/server/src/main/java/com/defold/extender/jetty/ExtenderJettyErrorHandler.java @@ -0,0 +1,84 @@ +package com.defold.extender.jetty; + +import java.io.IOException; + +import org.eclipse.jetty.http.HttpException; +import org.eclipse.jetty.http.HttpHeader; +import org.eclipse.jetty.http.HttpStatus; +import org.eclipse.jetty.io.Content; +import org.eclipse.jetty.server.Request; +import org.eclipse.jetty.server.Response; +import org.eclipse.jetty.server.handler.ErrorHandler; +import org.eclipse.jetty.util.Callback; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import com.defold.extender.log.Markers; + +/** + * Error handler installed on the Jetty {@link org.eclipse.jetty.server.Server}, i.e. the one used + * for requests that fail before they enter the servlet context - malformed HTTP, too large headers, + * too long URI, unsupported HTTP version. Those never reach Spring, so neither the controller + * exception handlers nor {@link com.defold.extender.RequestErrorAdvice} can see them; without this + * handler they are answered with an HTML page and are not logged at all. Errors raised inside the + * context still go through Spring Boot's own context error handler. + */ +public class ExtenderJettyErrorHandler extends ErrorHandler { + + private static final Logger LOGGER = LoggerFactory.getLogger(ExtenderJettyErrorHandler.class); + + private static final String MIME_TYPE = "text/plain"; + + private static final String LOG_MESSAGE = "Jetty rejected request {} {} from {} with status {}: {}"; + + public ExtenderJettyErrorHandler() { + setShowStacks(false); + setShowCauses(false); + setShowMessageInTitle(false); + setDefaultResponseMimeType(MIME_TYPE); + } + + @Override + public boolean handle(Request request, Response response, Callback callback) throws Exception { + final String message = (String)request.getAttribute(ERROR_MESSAGE); + final Throwable cause = (Throwable)request.getAttribute(ERROR_EXCEPTION); + final int code = (cause instanceof HttpException httpException) ? httpException.getCode() : response.getStatus(); + + if (HttpStatus.isServerError(code)) { + LOGGER.error(Markers.SERVER_ERROR, LOG_MESSAGE, + request.getMethod(), request.getHttpURI(), Request.getRemoteAddr(request), code, message, cause); + } else { + LOGGER.warn(LOG_MESSAGE, + request.getMethod(), request.getHttpURI(), Request.getRemoteAddr(request), code, message, cause); + } + + return super.handle(request, response, callback); + } + + @Override + protected void generateResponse(Request request, Response response, int code, String message, Throwable cause, Callback callback) throws IOException { + response.getHeaders().put(HttpHeader.CONTENT_TYPE, MIME_TYPE + ";charset=utf-8"); + Content.Sink.write(response, true, describe(code), callback); + } + + /** The body the user gets to see. What exactly Jetty disliked stays in the log. */ + static String describe(int code) { + final String explanation = switch (code) { + case HttpStatus.BAD_REQUEST_400 -> + "The server could not parse the request, so the build was never started. This usually means the request was truncated or malformed on the way to the server."; + case HttpStatus.REQUEST_TIMEOUT_408 -> + "The server timed out while waiting for the request to be sent."; + case HttpStatus.PAYLOAD_TOO_LARGE_413 -> + "The build request is too large."; + case HttpStatus.URI_TOO_LONG_414 -> + "The request URI is too long."; + case HttpStatus.REQUEST_HEADER_FIELDS_TOO_LARGE_431 -> + "The request headers are too large."; + case HttpStatus.HTTP_VERSION_NOT_SUPPORTED_505 -> + "The HTTP version used by the client is not supported by the server."; + default -> + "The request was rejected by the server before the build was started."; + }; + return String.format("%d %s%n%n%s%n", code, HttpStatus.getMessage(code), explanation); + } +} diff --git a/server/src/main/java/com/defold/extender/jetty/JettyRequestEventsHandler.java b/server/src/main/java/com/defold/extender/jetty/JettyRequestEventsHandler.java new file mode 100644 index 00000000..39abfe7a --- /dev/null +++ b/server/src/main/java/com/defold/extender/jetty/JettyRequestEventsHandler.java @@ -0,0 +1,48 @@ +package com.defold.extender.jetty; + +import java.util.Set; + +import org.eclipse.jetty.http.HttpStatus; +import org.eclipse.jetty.server.Handler; +import org.eclipse.jetty.server.Request; +import org.eclipse.jetty.server.Response; +import org.eclipse.jetty.util.Callback; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Logs requests that fail on the Jetty side. This complements {@link ExtenderJettyErrorHandler}: + * the error handler only runs when Jetty generates an error response, while this handler also sees + * failures that never produce one - a client that aborts mid upload, an idle timeout, or a failure + * after the response was already committed. All of those are client side problems, hence the + * warnings without com.defold.extender.log.Markers.SERVER_ERROR. + */ +public class JettyRequestEventsHandler extends Handler.Wrapper { + + private static final Logger LOGGER = LoggerFactory.getLogger(JettyRequestEventsHandler.class); + + // Already logged by ExtenderController's @ExceptionHandler methods, with more context than is + // available here, and for two of them with a SERVER_ERROR alert attached. + private static final Set STATUSES_LOGGED_BY_CONTROLLER = Set.of( + HttpStatus.UNPROCESSABLE_ENTITY_422, // handleExtenderException + HttpStatus.INTERNAL_SERVER_ERROR_500, // handleException + HttpStatus.NOT_IMPLEMENTED_501); // handleUsupportedExceptions + + @Override + public boolean handle(Request request, Response response, Callback callback) throws Exception { + // Not EventsHandler, which offers the same event only by wrapping the request and the + // response, adding an allocation to every chunk read and written. + Request.addCompletionListener(request, failure -> onComplete(request, response.getStatus(), failure)); + return super.handle(request, response, callback); + } + + private static void onComplete(Request request, int status, Throwable failure) { + if (failure != null) { + LOGGER.warn("Request {} {} from {} failed with status {}", + request.getMethod(), request.getHttpURI(), Request.getRemoteAddr(request), status, failure); + } else if (status >= 400 && !STATUSES_LOGGED_BY_CONTROLLER.contains(status)) { + LOGGER.warn("Request {} {} from {} completed with status {}", + request.getMethod(), request.getHttpURI(), Request.getRemoteAddr(request), status); + } + } +} diff --git a/server/src/main/java/com/defold/extender/jetty/JettyServerConfiguration.java b/server/src/main/java/com/defold/extender/jetty/JettyServerConfiguration.java new file mode 100644 index 00000000..c1c624c2 --- /dev/null +++ b/server/src/main/java/com/defold/extender/jetty/JettyServerConfiguration.java @@ -0,0 +1,24 @@ +package com.defold.extender.jetty; + +import org.eclipse.jetty.server.Handler; +import org.springframework.boot.jetty.ConfigurableJettyWebServerFactory; +import org.springframework.boot.web.server.WebServerFactoryCustomizer; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Configuration; + +@Configuration(proxyBeanMethods = false) +public class JettyServerConfiguration { + + @Bean + WebServerFactoryCustomizer extenderJettyCustomizer() { + return factory -> factory.addServerCustomizers(server -> { + // Must be the server level handler: the context one is Spring Boot's /error dispatch. + server.setErrorHandler(new ExtenderJettyErrorHandler()); + + final JettyRequestEventsHandler eventsHandler = new JettyRequestEventsHandler(); + final Handler currentHandler = server.getHandler(); + eventsHandler.setHandler(currentHandler); + server.setHandler(eventsHandler); + }); + } +} diff --git a/server/src/main/resources/application.yml b/server/src/main/resources/application.yml index 871666d4..52c0d1aa 100644 --- a/server/src/main/resources/application.yml +++ b/server/src/main/resources/application.yml @@ -1,7 +1,11 @@ server: port: 9000 + max-http-request-header-size: 16KB jetty: connection-idle-timeout: 600000 + # Jetty reuses maxFormKeys as the multipart part limit, i.e. the max number of files + # in a build request. + max-form-keys: 5000 extender: sdk: diff --git a/server/src/test/java/com/defold/extender/jetty/JettyErrorHandlingTest.java b/server/src/test/java/com/defold/extender/jetty/JettyErrorHandlingTest.java new file mode 100644 index 00000000..8a8c41a8 --- /dev/null +++ b/server/src/test/java/com/defold/extender/jetty/JettyErrorHandlingTest.java @@ -0,0 +1,269 @@ +package com.defold.extender.jetty; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; +import static org.junit.jupiter.api.Assertions.fail; + +import java.io.BufferedReader; +import java.io.IOException; +import java.io.InputStreamReader; +import java.io.OutputStream; +import java.net.Socket; +import java.nio.charset.StandardCharsets; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; + +import org.apache.http.HttpResponse; +import org.apache.http.client.methods.HttpGet; +import org.apache.http.client.methods.HttpPost; +import org.apache.http.client.methods.HttpUriRequest; +import org.apache.http.entity.ContentType; +import org.apache.http.entity.mime.MultipartEntityBuilder; +import org.apache.http.impl.client.CloseableHttpClient; +import org.apache.http.impl.client.HttpClients; +import org.apache.http.util.EntityUtils; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.parallel.Execution; +import org.junit.jupiter.api.parallel.ExecutionMode; +import org.slf4j.LoggerFactory; +import org.springframework.boot.SpringBootConfiguration; +import org.springframework.boot.autoconfigure.EnableAutoConfiguration; +import org.springframework.boot.test.context.SpringBootTest; +import org.springframework.boot.test.web.server.LocalServerPort; +import org.springframework.context.annotation.Bean; +import org.springframework.context.annotation.Import; +import org.springframework.security.config.annotation.web.builders.HttpSecurity; +import org.springframework.security.web.SecurityFilterChain; +import org.springframework.http.ResponseEntity; +import org.springframework.web.bind.annotation.GetMapping; +import org.springframework.web.bind.annotation.PostMapping; +import org.springframework.web.bind.annotation.RestController; +import org.springframework.web.multipart.MultipartHttpServletRequest; + +import com.defold.extender.RequestErrorAdvice; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.AppenderBase; + +/** + * Runs a real Jetty (MockMvc never runs Jetty's multipart parser, so it cannot reproduce any of + * this) on a random port, with a minimal context instead of the full Extender application. Requests + * are sent with the same HTTP client the Extender client and the remote builder use. + */ +@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT, + classes = JettyErrorHandlingTest.TestApp.class, + properties = { + "server.jetty.max-form-keys=50", + "server.max-http-request-header-size=16KB" + }) +// The log assertions below observe loggers shared by the whole JVM, so the test methods of this +// class must not run next to each other (parallel execution is on by default, see +// junit-platform.properties). +@Execution(ExecutionMode.SAME_THREAD) +public class JettyErrorHandlingTest { + + private static final int MAX_PARTS = 50; + + @SpringBootConfiguration + @EnableAutoConfiguration + @Import({ JettyServerConfiguration.class, RequestErrorAdvice.class }) + static class TestApp { + + @Bean + SecurityFilterChain permitAll(HttpSecurity http) throws Exception { + return http + .csrf(csrf -> csrf.disable()) + .authorizeHttpRequests(requests -> requests.anyRequest().permitAll()) + .build(); + } + + @Bean + UploadController uploadController() { + return new UploadController(); + } + } + + @RestController + static class UploadController { + @PostMapping("/upload") + String upload(MultipartHttpServletRequest request) { + return String.valueOf(request.getFileMap().size()); + } + + @GetMapping("/boom") + ResponseEntity boom() { + return ResponseEntity.internalServerError().body("boom"); + } + } + + private static final List> LOGGERS_UNDER_TEST = List.of( + ExtenderJettyErrorHandler.class, JettyRequestEventsHandler.class, RequestErrorAdvice.class); + + @LocalServerPort + private int port; + + private final List loggedMessages = new CopyOnWriteArrayList<>(); + private final AppenderBase appender = new AppenderBase<>() { + @Override + protected void append(ILoggingEvent event) { + loggedMessages.add(event.getFormattedMessage()); + } + }; + + @BeforeEach + public void captureLogs() { + loggedMessages.clear(); + appender.start(); + LOGGERS_UNDER_TEST.forEach(logger -> ((Logger)LoggerFactory.getLogger(logger)).addAppender(appender)); + } + + @AfterEach + public void releaseLogs() { + LOGGERS_UNDER_TEST.forEach(logger -> ((Logger)LoggerFactory.getLogger(logger)).detachAppender(appender)); + appender.stop(); + } + + @Test + public void uploadWithTooManyFilesIsRejectedWithAnExplanation() throws IOException { + Response response = upload(MAX_PARTS + 1); + + assertEquals(413, response.status()); + assertTrue(response.contentType().startsWith("text/plain"), "Unexpected content type: " + response.contentType()); + assertTrue(response.body().contains(String.format("too many files (%d, the limit is %d)", MAX_PARTS + 1, MAX_PARTS)), + "Unexpected body: " + response.body()); + + assertLogged("too many files"); + assertLogged("completed with status 413"); + } + + @Test + public void uploadWithinTheLimitSucceeds() throws IOException { + Response response = upload(MAX_PARTS - 1); + + assertEquals(200, response.status()); + assertEquals(String.valueOf(MAX_PARTS - 1), response.body()); + } + + @Test + public void statusesLoggedByTheControllerAreNotLoggedAgain() throws IOException { + assertEquals(500, execute(new HttpGet(url("/boom"))).status()); + // Sequential, so the 500 has certainly been seen by the time the 404 is logged. + assertEquals(404, execute(new HttpGet(url("/not-mapped"))).status()); + + assertLogged("completed with status 404"); + assertFalse(loggedMessages.stream().anyMatch(logged -> logged.contains("status 500")), + "The 500 is logged by ExtenderController's exception handlers, not here: " + loggedMessages); + } + + @Test + public void malformedMultipartBodiesAreRejectedWithAnExplanation() throws IOException { + // A body that never contains the announced boundary. + String body = "not a multipart body\r\n"; + String response = sendRaw("POST /upload HTTP/1.1\r\n" + + "Host: localhost\r\n" + + "Connection: close\r\n" + + "Content-Type: multipart/form-data; boundary=aBoundary\r\n" + + "Content-Length: " + body.length() + "\r\n" + + "\r\n" + + body); + + assertTrue(response.startsWith("HTTP/1.1 400"), "Unexpected response: " + response); + assertTrue(response.contains("not a valid multipart request"), "Unexpected response: " + response); + assertLogged("not a valid multipart request"); + } + + @Test + public void oversizedHeadersAreRejectedByTheJettyErrorHandler() throws IOException { + HttpGet request = new HttpGet(url("/upload")); + request.addHeader("X-Too-Large", "a".repeat(32 * 1024)); + + Response response = execute(request); + + assertEquals(431, response.status()); + assertTrue(response.contentType().startsWith("text/plain"), "Unexpected content type: " + response.contentType()); + assertTrue(response.body().contains("The request headers are too large"), "Unexpected body: " + response.body()); + assertLogged("Jetty rejected request GET /upload"); + } + + @Test + public void malformedRequestsAreRejectedByTheJettyErrorHandler() throws IOException { + String response = sendRaw("GET / HTTP/1.1\r\nHost: localhost\r\nConnection: close\r\nthis-is-not-a-header\r\n\r\n"); + + assertTrue(response.startsWith("HTTP/1.1 400"), "Unexpected response: " + response); + assertTrue(response.contains("text/plain"), "Unexpected response: " + response); + assertTrue(response.contains("The server could not parse the request"), "Unexpected response: " + response); + assertLogged("Jetty rejected request"); + } + + private record Response(int status, String contentType, String body) {} + + /** Some of these are logged after the response is written, so give them a moment to arrive. */ + private void assertLogged(String message) { + for (int attempt = 0; attempt < 100; attempt++) { + if (loggedMessages.stream().anyMatch(logged -> logged.contains(message))) { + return; + } + try { + Thread.sleep(20); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + break; + } + } + fail(String.format("Expected a log message containing '%s', but got: %s", message, loggedMessages)); + } + + private String url(String path) { + return String.format("http://localhost:%d%s", port, path); + } + + private Response upload(int fileCount) throws IOException { + MultipartEntityBuilder entityBuilder = MultipartEntityBuilder.create(); + for (int i = 0; i < fileCount; i++) { + final String filename = String.format("file%d.txt", i); + entityBuilder.addBinaryBody(filename, filename.getBytes(StandardCharsets.UTF_8), + ContentType.APPLICATION_OCTET_STREAM, filename); + } + + HttpPost request = new HttpPost(url("/upload")); + request.setEntity(entityBuilder.build()); + return execute(request); + } + + private Response execute(HttpUriRequest request) throws IOException { + try (CloseableHttpClient client = HttpClients.createDefault()) { + HttpResponse response = client.execute(request); + String contentType = response.getEntity().getContentType() == null + ? "" : response.getEntity().getContentType().getValue(); + return new Response(response.getStatusLine().getStatusCode(), contentType, + EntityUtils.toString(response.getEntity(), StandardCharsets.UTF_8).trim()); + } + } + + /** + * Reads until the server closes the connection, so every request passed in must ask for + * "Connection: close" - the timeout is there to fail fast rather than stall a CI run for the + * ten minute idle timeout if one ever does not. + */ + private String sendRaw(String request) throws IOException { + try (Socket socket = new Socket("localhost", port)) { + socket.setSoTimeout(10_000); + OutputStream output = socket.getOutputStream(); + output.write(request.getBytes(StandardCharsets.ISO_8859_1)); + output.flush(); + + StringBuilder response = new StringBuilder(); + try (BufferedReader reader = new BufferedReader(new InputStreamReader(socket.getInputStream(), StandardCharsets.ISO_8859_1))) { + String line; + while ((line = reader.readLine()) != null) { + response.append(line).append('\n'); + } + } + return response.toString(); + } + } +}