From 19e97075e465e8bdae96e07c11b1bceba8edc9ad Mon Sep 17 00:00:00 2001 From: Ryan Doherty Date: Sat, 30 Nov 2024 10:03:35 -0500 Subject: [PATCH 1/4] Write requests to file to test sizes before processing; still log request body on error --- .../service/filter/RequestLoggingFilter.java | 260 ++++++++++++------ .../wdk/service/service/AnswerService.java | 14 - 2 files changed, 173 insertions(+), 101 deletions(-) diff --git a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java index f0637470ee..f011e65f5e 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java +++ b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java @@ -2,51 +2,86 @@ import static org.gusdb.fgputil.FormatUtil.NL; -import java.io.ByteArrayInputStream; +import java.io.BufferedReader; +import java.io.FileInputStream; +import java.io.FileOutputStream; +import java.io.FileReader; import java.io.IOException; +import java.io.InputStream; +import java.io.OutputStream; +import java.io.Reader; +import java.nio.file.Files; +import java.nio.file.Path; import java.util.List; import java.util.Map.Entry; +import java.util.Optional; import java.util.function.Consumer; import java.util.function.Function; import javax.annotation.Priority; -import javax.ws.rs.ProcessingException; +import javax.servlet.ServletContext; +import javax.ws.rs.HttpMethod; import javax.ws.rs.WebApplicationException; import javax.ws.rs.container.ContainerRequestContext; import javax.ws.rs.container.ContainerRequestFilter; import javax.ws.rs.container.ContainerResponseContext; import javax.ws.rs.container.ContainerResponseFilter; -import javax.ws.rs.core.MediaType; +import javax.ws.rs.core.Context; import javax.ws.rs.core.MultivaluedMap; +import javax.ws.rs.core.Response; +import javax.ws.rs.core.Response.Status; import javax.ws.rs.core.UriInfo; import javax.ws.rs.ext.WriterInterceptor; import javax.ws.rs.ext.WriterInterceptorContext; import org.apache.log4j.Level; import org.apache.log4j.Logger; -import org.glassfish.jersey.server.ContainerRequest; +import org.gusdb.wdk.controller.ContextLookup; import org.gusdb.wdk.service.service.SystemService; import org.json.JSONArray; -import org.json.JSONException; import org.json.JSONObject; +/** + * Logs receipt of WDK service requests (HTTP method, path, query parameters), + * and completion (duration, response status, request body (if error)). + * + * This filter is also responsible for limiting the size of request bodies + * (currently 20 MiB). To accomplish this, regardless of Content-Size header, + * it streams the body into a temporary file and checks file size, before + * setting the request input stream to a FileInputStream on the file. + * ResponseFilter and WriterInterceptor methods are responsible for deleting + * the file during response completion. + */ @Priority(200) public class RequestLoggingFilter implements ContainerRequestFilter, ContainerResponseFilter, WriterInterceptor { private static final Logger LOG = Logger.getLogger(RequestLoggingFilter.class); + // log level for request log private static final Level LOG_LEVEL = Level.INFO; - private static final String EMPTY_ENTITY = ""; - private static final String FORM_ENTITY = ""; + private enum ResponseLoggingAction { + NONE, // no body + THROW_413_CONTENT_TOO_LARGE, // body too large to process + LOG_BODY_ON_ERROR_AND_DELETE; // body small enough to process + } private static final String OMIT_REQUEST_LOGGING_PROP_KEY = "omitRequestLogging"; private static final String HTTP_RESPONSE_STATUS_PROP_KEY = "httpResponseStatus"; + private static final String REQUEST_LOGGING_ACTION_PROP_KEY = "requestLoggingAction"; + private static final String REQUEST_BODY_FILE_PATH_PROP_KEY = "requestBodyFilePath"; + + private static final long MAX_REQUEST_BODY_MEBIBYTES = 20; + private static final long MAX_REQUEST_BODY_BYTES = MAX_REQUEST_BODY_MEBIBYTES * 1048576; + private static final long MAX_REQUEST_LOGGING_BYTES = 10000; // 10k bytes (approx chars) public static boolean isLogEnabled() { return LOG.isEnabledFor(LOG_LEVEL); } + @Context + private ServletContext _servletContext; + @Override public void filter(ContainerRequestContext requestContext) throws IOException { @@ -57,16 +92,82 @@ public void filter(ContainerRequestContext requestContext) throws IOException { // tell outgoing request classes whether to skip logging requestContext.setProperty(OMIT_REQUEST_LOGGING_PROP_KEY, omitRequestLogging); + // stream request body to temp file to check size before trying to load into memory + Optional requestBodyFile = saveRequestBody(requestContext); + + // determine action and set on request + ResponseLoggingAction action = determineAction(requestBodyFile); + requestContext.setProperty(REQUEST_LOGGING_ACTION_PROP_KEY, action); + + if (action == ResponseLoggingAction.THROW_413_CONTENT_TOO_LARGE) { + + // tell response filters not to do anything with the file since we are deleting it + requestContext.setProperty(REQUEST_LOGGING_ACTION_PROP_KEY, ResponseLoggingAction.NONE); + + // delete the temporary file + Files.delete(requestBodyFile.get()); + + // abort handling of this request and tell why + requestContext.abortWith(Response + .status(Status.REQUEST_ENTITY_TOO_LARGE) + .entity("Response Body Too Large. Must not exceed " + MAX_REQUEST_BODY_MEBIBYTES + " MiB.") + .build()); + + return; + } + + // if present, request body is small enough to process + if (requestBodyFile.isPresent()) { + requestContext.setProperty(REQUEST_BODY_FILE_PATH_PROP_KEY, requestBodyFile.get()); + requestContext.setEntityStream(new FileInputStream(requestBodyFile.get().toFile())); + } + // explicitly check if enabled to not impact performance if logging is turned off if (!omitRequestLogging && isLogEnabled()) { - logRequest( + logRequestStart( requestContext.getMethod(), - requestContext.getUriInfo(), - getRequestBody(requestContext)); + requestContext.getUriInfo()); + } + } + + private ResponseLoggingAction determineAction(Optional requestBodyFile) throws IOException { + if (requestBodyFile.isEmpty()) { + return ResponseLoggingAction.NONE; + } + + Path path = requestBodyFile.get(); + long fileSize = Files.size(path); + + // check against max size limit + if (fileSize > MAX_REQUEST_BODY_BYTES) { + return ResponseLoggingAction.THROW_413_CONTENT_TOO_LARGE; } + + return ResponseLoggingAction.LOG_BODY_ON_ERROR_AND_DELETE; } - public static void logRequest(String method, UriInfo uriInfo, String body) { + private Optional saveRequestBody(ContainerRequestContext requestContext) { + if (requestContext.getMethod().equals(HttpMethod.GET)) { + // no body expected + return Optional.empty(); + } + try (InputStream in = requestContext.getEntityStream()) { + if (in == null) { + return Optional.empty(); + } + Path tmpDir = ContextLookup.getWdkModel(_servletContext).getModelConfig().getWdkTempDir(); + Path tempFile = Files.createTempFile(tmpDir, "wdkRequest-", null); + try (OutputStream out = new FileOutputStream(tempFile.toFile())) { + in.transferTo(out); + return Optional.of(tempFile); + } + } + catch (IOException e) { + throw new RuntimeException("Unable to write request body to temporary file.", e); + } + } + + public static void logRequestStart(String method, UriInfo uriInfo) { StringBuilder log = new StringBuilder("HTTP ") .append(method).append(" /").append(uriInfo.getPath()); @@ -77,11 +178,6 @@ public static void logRequest(String method, UriInfo uriInfo, String body) { log.append(NL).append("Query Parameters: ").append(queryToJson(query)); } - // add request body if present - if (body != null && !body.isEmpty() && !EMPTY_ENTITY.equals(body)) { - log.append(NL).append("Request Body: ").append(body); - } - LOG.log(LOG_LEVEL, log.toString()); } @@ -93,64 +189,6 @@ private static String queryToJson(MultivaluedMap map) { return json.toString(2); } - private static String getRequestBody(ContainerRequestContext requestContext) { - String contentType = requestContext.getHeaderString("Content-Type"); - if (contentType == null) - contentType = MediaType.APPLICATION_JSON; // assume JSON input if unspecified - switch (contentType) { - case MediaType.APPLICATION_FORM_URLENCODED: - return FORM_ENTITY; - case MediaType.APPLICATION_JSON: - case MediaType.APPLICATION_JSON + "; charset=utf-8": - case MediaType.APPLICATION_JSON + "; charset=UTF-8": - return formatJson(getRequestBodyText(requestContext)); - case MediaType.TEXT_PLAIN: - case MediaType.TEXT_XML: - return getRequestBodyText(requestContext); - default: - // assume JSON - return "Indeterminant data of type " + contentType; - } - } - - private static String getRequestBodyText(ContainerRequestContext requestContext) { - ContainerRequest context = (ContainerRequest) requestContext; - try { - if (context.bufferEntity()) { - String entity = context.readEntity(String.class); - requestContext.setEntityStream(new ByteArrayInputStream(entity.getBytes())); - return entity; - } - else { - return EMPTY_ENTITY; - } - } - catch (ProcessingException e) { - LOG.error("Could not read request entity.", e); - return EMPTY_ENTITY; - } - } - - public static String formatJson(String entity) { - if (entity != null && !entity.isEmpty()) { - try { - if (entity.startsWith("{")) { - return new JSONObject(entity).toString(2); - } - else if (entity.startsWith("[")){ - return new JSONArray(entity).toString(2); - } - else { - return entity; - } - } - catch (JSONException e) { - return entity; - } - } - return EMPTY_ENTITY; - } - @Override public void filter(ContainerRequestContext context, ContainerResponseContext responseContext) throws IOException { @@ -158,45 +196,93 @@ public void filter(ContainerRequestContext context, ContainerResponseContext res boolean hasResponseBody = responseContext.getEntity() != null; int httpStatus = responseContext.getStatus(); if (hasResponseBody) { - // pass along the response status to the interceptor to log after response body is written + // pass along the content type and response status to the interceptor to log after response body is written context.setProperty(HTTP_RESPONSE_STATUS_PROP_KEY, httpStatus); } else { // request is complete; log status - logRequestCompletion(httpStatus, "empty", context::getProperty, context::removeProperty); + logRequestCompletion(httpStatus, "empty", toGetAndRemove(context::getProperty, context::removeProperty)); } } @Override public void aroundWriteTo(WriterInterceptorContext context) throws IOException, WebApplicationException { - // get HTTP status passed along by the filter() method, then remove + // get content type and HTTP status passed along by the filter() method, then remove int httpStatus = (Integer)context.getProperty(HTTP_RESPONSE_STATUS_PROP_KEY); context.removeProperty(HTTP_RESPONSE_STATUS_PROP_KEY); + Function getAndRemoveProp = toGetAndRemove(context::getProperty, context::removeProperty); try { // write the response context.proceed(); // response written successfully; log status - logRequestCompletion(httpStatus, "written successfully", context::getProperty, context::removeProperty); + logRequestCompletion(httpStatus, "written successfully", getAndRemoveProp); } catch (Exception e) { // exception while writing response body; log error, then status LOG.error("Failure to write response body", e); - logRequestCompletion(httpStatus, "write failed", context::getProperty, context::removeProperty); + logRequestCompletion(httpStatus, "write failed", getAndRemoveProp); throw e; } } - private static void logRequestCompletion(int httpStatus, String bodyWriteStatus, - Function getter, Consumer remover) { - // skip logging as requested - Boolean omitRequestLogging = (Boolean)getter.apply(OMIT_REQUEST_LOGGING_PROP_KEY); - remover.accept(OMIT_REQUEST_LOGGING_PROP_KEY); + private static Function toGetAndRemove(Function getter, Consumer remover) { + return key -> { + Object obj = getter.apply(key); + remover.accept(key); + return obj; + }; + } + + private static void logRequestCompletion(int httpStatus, String bodyWriteStatus, Function getAndRemoveProp) { + + // gather parameters for what action should be taken, then remove props from context object + Boolean omitRequestLogging = (Boolean)getAndRemoveProp.apply(OMIT_REQUEST_LOGGING_PROP_KEY); + ResponseLoggingAction action = (ResponseLoggingAction)getAndRemoveProp.apply(REQUEST_LOGGING_ACTION_PROP_KEY); + Path filePath = (Path)getAndRemoveProp.apply(REQUEST_BODY_FILE_PATH_PROP_KEY); // will be null if action is NONE + boolean isErrorStatus = httpStatus >= 500 && httpStatus < 600; + + // if property not found, then this request went unmatched; can ignore. + if (omitRequestLogging == null) return; + + if (action != ResponseLoggingAction.NONE) { + + // decide whether and what to log + if (!omitRequestLogging && isLogEnabled()) { + String bodyText = !isErrorStatus ? "" : ", Request Body:\n" + readRequestBody(filePath); + LOG.log(LOG_LEVEL, "Request completed [" + httpStatus + "]" + bodyText); + } - // if property not found, then this request went unmatched; can ignore. If present, omit as requested. - if (omitRequestLogging != null && !omitRequestLogging) { - LOG.log(LOG_LEVEL, "Request completed [" + httpStatus + "]; response body " + bodyWriteStatus); + // delete the temporary request body file + try { + Files.delete(filePath); + } + catch (IOException e) { + LOG.warn("Unable to delete temporary body file: " + filePath); + } } } + /** + * Reads the request body file but only up to the max number of logging bytes and returns as a String + * + * @param filePath path of temporary file + * @return possibly truncated content of request body + * @throws IOException + */ + private static String readRequestBody(Path filePath) { + try (Reader r = new BufferedReader(new FileReader(filePath.toFile()))) { + StringBuilder resultBuilder = new StringBuilder(); + int count = 0; + int next; + while (((next = r.read()) != -1) && count < MAX_REQUEST_LOGGING_BYTES) { + resultBuilder.append((char)next); + count++; + } + return resultBuilder.toString(); + } + catch (IOException e) { + return "Error reading request body from file: " + e.getMessage(); + } + } } diff --git a/Service/src/main/java/org/gusdb/wdk/service/service/AnswerService.java b/Service/src/main/java/org/gusdb/wdk/service/service/AnswerService.java index cb56306ba1..2d9757db8f 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/service/AnswerService.java +++ b/Service/src/main/java/org/gusdb/wdk/service/service/AnswerService.java @@ -22,7 +22,6 @@ import javax.ws.rs.core.Response; import javax.ws.rs.core.Response.ResponseBuilder; import javax.ws.rs.core.StreamingOutput; -import javax.ws.rs.core.UriInfo; import org.apache.log4j.Logger; import org.gusdb.fgputil.FormatUtil; @@ -60,7 +59,6 @@ import org.gusdb.wdk.model.user.User; import org.gusdb.wdk.service.annotation.InSchema; import org.gusdb.wdk.service.annotation.OutSchema; -import org.gusdb.wdk.service.filter.RequestLoggingFilter; import org.gusdb.wdk.service.request.answer.AnswerSpecServiceFormat; import org.gusdb.wdk.service.request.exception.DataValidationException; import org.gusdb.wdk.service.request.exception.RequestMisformatException; @@ -226,7 +224,6 @@ public Response createCustomReportAnswerFromForm( @PathParam(REPORT_NAME_PATH_PARAM) String reportName, @FormParam("data") String data) throws WdkModelException, DataValidationException, RequestMisformatException { - preHandleFormRequest(getUriInfo(), data); return createCustomReportAnswer(reportName, new JSONObject(data)); } @@ -510,15 +507,4 @@ private static ResponseBuilder applyDisposition(ResponseBuilder response, return response; } - public static void preHandleFormRequest(UriInfo uriInfo, String data) throws RequestMisformatException { - // log this request's JSON here since filter will not log form data - if (RequestLoggingFilter.isLogEnabled()) { - RequestLoggingFilter.logRequest("POST", uriInfo, - RequestLoggingFilter.formatJson(data)); - } - if (data == null || data.isEmpty()) { - throw new RequestMisformatException("Request JSON cannot be empty. " + - "If submitting a form, include the 'data' input parameter."); - } - } } From c9b6f34e7814d87893ff49fba856a7a02e72c14d Mon Sep 17 00:00:00 2001 From: Ryan Doherty Date: Sat, 30 Nov 2024 10:11:31 -0500 Subject: [PATCH 2/4] Remove calls to deleted method --- .../java/org/gusdb/wdk/service/service/user/BasketService.java | 1 - .../java/org/gusdb/wdk/service/service/user/StepService.java | 1 - 2 files changed, 2 deletions(-) diff --git a/Service/src/main/java/org/gusdb/wdk/service/service/user/BasketService.java b/Service/src/main/java/org/gusdb/wdk/service/service/user/BasketService.java index bd15255ff8..6af00cecbb 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/service/user/BasketService.java +++ b/Service/src/main/java/org/gusdb/wdk/service/service/user/BasketService.java @@ -315,7 +315,6 @@ public Response createCustomReportAnswerFromForm( @PathParam(REPORT_NAME_PATH_PARAM) final String reportName, @FormParam("data") String data) throws WdkModelException, DataValidationException, RequestMisformatException { - AnswerService.preHandleFormRequest(getUriInfo(), data); return createCustomReportAnswer(basketName, reportName, new JSONObject(data)); } diff --git a/Service/src/main/java/org/gusdb/wdk/service/service/user/StepService.java b/Service/src/main/java/org/gusdb/wdk/service/service/user/StepService.java index 6230a23e7d..4ae2cd5cfc 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/service/user/StepService.java +++ b/Service/src/main/java/org/gusdb/wdk/service/service/user/StepService.java @@ -305,7 +305,6 @@ public Response createCustomReportAnswerFromForm( @PathParam(REPORT_NAME_PATH_PARAM) String reportName, @FormParam("data") String data) throws WdkModelException, DataValidationException, RequestMisformatException { - AnswerService.preHandleFormRequest(getUriInfo(), data); return createCustomReportAnswer(stepId, reportName, new JSONObject(data)); } From fc3dded2d39abfb25bc93b97b88606defb89b158 Mon Sep 17 00:00:00 2001 From: Ryan Doherty Date: Sat, 30 Nov 2024 19:24:01 -0500 Subject: [PATCH 3/4] Fix comments --- .../org/gusdb/wdk/service/filter/RequestLoggingFilter.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java index f011e65f5e..6869b46808 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java +++ b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java @@ -196,7 +196,7 @@ public void filter(ContainerRequestContext context, ContainerResponseContext res boolean hasResponseBody = responseContext.getEntity() != null; int httpStatus = responseContext.getStatus(); if (hasResponseBody) { - // pass along the content type and response status to the interceptor to log after response body is written + // pass along the response status to the interceptor to log after response body is written context.setProperty(HTTP_RESPONSE_STATUS_PROP_KEY, httpStatus); } else { @@ -207,7 +207,7 @@ public void filter(ContainerRequestContext context, ContainerResponseContext res @Override public void aroundWriteTo(WriterInterceptorContext context) throws IOException, WebApplicationException { - // get content type and HTTP status passed along by the filter() method, then remove + // get HTTP status passed along by the filter() method, then remove int httpStatus = (Integer)context.getProperty(HTTP_RESPONSE_STATUS_PROP_KEY); context.removeProperty(HTTP_RESPONSE_STATUS_PROP_KEY); Function getAndRemoveProp = toGetAndRemove(context::getProperty, context::removeProperty); From 1e7f3c5182670a02563370f8dc66ba3c0e0e1cfc Mon Sep 17 00:00:00 2001 From: Ryan Doherty Date: Sat, 7 Dec 2024 00:08:34 -0500 Subject: [PATCH 4/4] Rename max bytes constants for clarity --- .../service/filter/RequestLoggingFilter.java | 22 +++++++++---------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java index 6869b46808..779badf37e 100644 --- a/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java +++ b/Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java @@ -46,11 +46,11 @@ * and completion (duration, response status, request body (if error)). * * This filter is also responsible for limiting the size of request bodies - * (currently 20 MiB). To accomplish this, regardless of Content-Size header, - * it streams the body into a temporary file and checks file size, before - * setting the request input stream to a FileInputStream on the file. - * ResponseFilter and WriterInterceptor methods are responsible for deleting - * the file during response completion. + * (currently 15 MiB, or ~30 mib in memory). To accomplish this, regardless + * of Content-Size header, it streams the body into a temporary file and checks + * file size, before setting the request input stream to a FileInputStream on + * the file. ResponseFilter and WriterInterceptor methods are responsible for + * deleting the file during response completion. */ @Priority(200) public class RequestLoggingFilter implements ContainerRequestFilter, ContainerResponseFilter, WriterInterceptor { @@ -71,9 +71,9 @@ private enum ResponseLoggingAction { private static final String REQUEST_LOGGING_ACTION_PROP_KEY = "requestLoggingAction"; private static final String REQUEST_BODY_FILE_PATH_PROP_KEY = "requestBodyFilePath"; - private static final long MAX_REQUEST_BODY_MEBIBYTES = 20; - private static final long MAX_REQUEST_BODY_BYTES = MAX_REQUEST_BODY_MEBIBYTES * 1048576; - private static final long MAX_REQUEST_LOGGING_BYTES = 10000; // 10k bytes (approx chars) + private static final long MAX_REQUEST_BODY_BYTES_IN_MEMORY = 30 /* mib */ * 1048576; + private static final long MAX_REQUEST_BODY_BYTES_IN_FILE = MAX_REQUEST_BODY_BYTES_IN_MEMORY / 2; + private static final long MAX_REQUEST_LOGGING_BYTES_IN_FILE = 5000; // approx 5k chars (will occupy 10k bytes in memory) public static boolean isLogEnabled() { return LOG.isEnabledFor(LOG_LEVEL); @@ -110,7 +110,7 @@ public void filter(ContainerRequestContext requestContext) throws IOException { // abort handling of this request and tell why requestContext.abortWith(Response .status(Status.REQUEST_ENTITY_TOO_LARGE) - .entity("Response Body Too Large. Must not exceed " + MAX_REQUEST_BODY_MEBIBYTES + " MiB.") + .entity("Response Body Too Large. Must not exceed " + (MAX_REQUEST_BODY_BYTES_IN_FILE / 1000000) + " MB.") .build()); return; @@ -139,7 +139,7 @@ private ResponseLoggingAction determineAction(Optional requestBodyFile) th long fileSize = Files.size(path); // check against max size limit - if (fileSize > MAX_REQUEST_BODY_BYTES) { + if (fileSize > MAX_REQUEST_BODY_BYTES_IN_FILE) { return ResponseLoggingAction.THROW_413_CONTENT_TOO_LARGE; } @@ -274,7 +274,7 @@ private static String readRequestBody(Path filePath) { StringBuilder resultBuilder = new StringBuilder(); int count = 0; int next; - while (((next = r.read()) != -1) && count < MAX_REQUEST_LOGGING_BYTES) { + while (((next = r.read()) != -1) && count < MAX_REQUEST_LOGGING_BYTES_IN_FILE) { resultBuilder.append((char)next); count++; }