Request log mem leak

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 = "<empty>";
-  private static final String FORM_ENTITY = "<form_data>";
+  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<Path> 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<Path> 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<Path> 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<String, String> 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 {
@@ -163,7 +201,7 @@ public void filter(ContainerRequestContext context, ContainerResponseContext res
     }
     else {
       // request is complete; log status
-      logRequestCompletion(httpStatus, "empty", context::getProperty, context::removeProperty);
+      logRequestCompletion(httpStatus, "empty", toGetAndRemove(context::getProperty, context::removeProperty));
     }
   }
 
@@ -172,31 +210,79 @@ public void aroundWriteTo(WriterInterceptorContext context) throws IOException,
     // 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<String,Object> 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<String,Object> getter, Consumer<String> 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<String,Object> toGetAndRemove(Function<String,Object> getter, Consumer<String> remover) {
+    return key -> {
+      Object obj = getter.apply(key);
+      remover.accept(key);
+      return obj;
+    };
+  }
+
+  private static void logRequestCompletion(int httpStatus, String bodyWriteStatus, Function<String,Object> 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();
+    }
+  }
 
 }

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.");
-    }
-  }
 }