Skip to content

Commit

Permalink
Merge pull request #110 from VEuPathDB/request-log-mem-leak
Browse files Browse the repository at this point in the history 
Request log mem leak
  • Loading branch information
@ryanrdoherty
ryanrdoherty authored Dec 7, 2024
2 parents 22dd5ea + 1e7f3c5 commit 11fdaff
Show file tree
Hide file tree
Showing 4 changed files with 171 additions and 101 deletions.
256 changes: 171 additions & 85 deletions Service/src/main/java/org/gusdb/wdk/service/filter/RequestLoggingFilter.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 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 {

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_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);
}

@Context
private ServletContext _servletContext;

@Override
public void filter(ContainerRequestContext requestContext) throws IOException {

Expand All @@ -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_BYTES_IN_FILE / 1000000) + " MB.")
.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_IN_FILE) {
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());
Expand All @@ -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());
}

Expand All @@ -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 {
Expand All @@ -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));
}
}

Expand All @@ -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_IN_FILE) {
resultBuilder.append((char)next);
count++;
}
return resultBuilder.toString();
}
catch (IOException e) {
return "Error reading request body from file: " + e.getMessage();
}
}

}
14 changes: 0 additions & 14 deletions Service/src/main/java/org/gusdb/wdk/service/service/AnswerService.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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));
}

Expand Down Expand Up @@ -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.");
}
}
}
Loading

0 comments on commit 11fdaff

Please sign in to comment.