ContentCachingResponseWrapper Produces Empty Respo

Question

I'm trying to implement filter for logging requests and responses in Spring MVC application. I use the following code:

@Component
public class LoggingFilter extends OncePerRequestFilter {

    private static final Logger LOGGER = LoggerFactory.getLogger(LoggingFilter.class);

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {

        ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);

        LOGGER.debug(REQUEST_MESSAGE_FORMAT, requestWrapper.getRequestURI(), requestWrapper.getMethod(), requestWrapper.getContentType(),
                new ServletServerHttpRequest(requestWrapper).getHeaders(), IOUtils.toString(requestWrapper.getInputStream(), UTF_8));

        filterChain.doFilter(requestWrapper, responseWrapper);

        LOGGER.debug(RESPONSE_MESSAGE_FORMAT, responseWrapper.getStatus(), responseWrapper.getContentType(),
                new ServletServerHttpResponse(responseWrapper).getHeaders(), IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8));
    }
}

So, I get my request and respone logged as expected. Here are the logs:

2016-10-08 19:10:11.212 DEBUG 11072 --- [qtp108982313-19] by.kolodyuk.logging.LoggingFilter
----------------------------
ID: 1
URI: /resources/1
Http-Method: GET
Content-Type: null
Headers: {User-Agent=[curl/7.41.0], Accept=[*/*], Host=[localhost:9015]}
Body: 
--------------------------------------
2016-10-08 19:10:11.277 DEBUG 11072 --- [qtp108982313-19] by.kolodyuk.logging.LoggingFilter
----------------------------
ID: 1
Response-Code: 200
Content-Type: application/json;charset=UTF-8
Headers: {}
Body: {"id":"1"}
--------------------------------------

However, the empty response is returned. Here's the output from curl:

$ curl http://localhost:9015/resources/1 --verbose
*   Trying ::1...
* Connected to localhost (::1) port 9015 (#0)
> GET /resources/1 HTTP/1.1
> User-Agent: curl/7.41.0
> Host: localhost:9015
> Accept: */*
>
< HTTP/1.1 200 OK
< Date: Sat, 08 Oct 2016 17:10:11 GMT
< Content-Type: application/json;charset=UTF-8
< Content-Length: 0
<
* Connection #0 to host localhost left intact

Any ideas?

Thanks

Answer 1

The pattern I like to use is to split this into 2 filters, one for extracting the raw body and another one to do the logging - feels a more SRP.

@Slf4j        // lombok logging
@Component    // spring loads filter into it's filter chain
@Order(1)     // Best if this goes first (or early in filter chain)
public class CachingBodyFilter implements Filter {

    @Override
    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) {
        ContentCachingRequestWrapper reqWrapper = new ContentCachingRequestWrapper((HttpServletRequest) req);
        ContentCachingResponseWrapper resWrapper = new ContentCachingResponseWrapper((HttpServletResponse) res);
        try {
            chain.doFilter(reqWrapper, resWrapper);
            resWrapper.copyBodyToResponse();  // Necessary (see answer by StasKolodyuk above)
        } catch (IOException | ServletException e) {
            log.error("Error extracting body", e);
        }
    }

}

And then we create another filter to do the logging part.

@Slf4j
@Component
@Order(2)     // This needs to come after `CachingBodyFilter`
public class PayloadLogFilter implements Filter {

    public void doFilter(ServletRequest req, ServletResponse res, FilterChain chain) throws IOException, ServletException {
        chain.doFilter(req, res);

        if (req instanceof ContentCachingRequestWrapper) {
            ContentCachingRequestWrapper reqWrapper = (ContentCachingRequestWrapper) req;
            String payload = new String (reqWrapper.getContentAsByteArray(), "utf-8");
            log.debug("Request [ {} ] has payload [ {} ]", reqWrapper.getRequestURI(), payload);
        }
    }

}

A nice advantage of splitting these up is that other classes (e.g. a Spring AOP interceptor or a Spring controller) can also access / use the HTTP body.

Answer 2

Finally solved the problem. Here is the perfect solution:

import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper;
import org.apache.commons.io.IOUtils;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.http.*;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.BufferedReader;
import java.io.IOException;
import java.io.InputStreamReader;
import java.net.URI;
import java.util.Enumeration;
import java.util.Map;

import static java.nio.charset.StandardCharsets.UTF_8;
import static net.logstash.logback.marker.Markers.appendFields;

@Component
public class LoggingFilter extends OncePerRequestFilter {

  private static final Logger LOGGER = LoggerFactory.getLogger(LoggingFilter.class);

  @Autowired
  private ObjectMapper objectMapper;

  @Override
  protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, FilterChain filterChain) throws ServletException, IOException {

    ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(httpServletRequest);
    ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(httpServletResponse);

    filterChain.doFilter(requestWrapper, responseWrapper);

    String requestUrl = requestWrapper.getRequestURL().toString();
    HttpHeaders requestHeaders = new HttpHeaders();
    Enumeration headerNames = requestWrapper.getHeaderNames();
    while (headerNames.hasMoreElements()) {
      String headerName = (String) headerNames.nextElement();
      requestHeaders.add(headerName, requestWrapper.getHeader(headerName));
    }
    HttpMethod httpMethod = HttpMethod.valueOf(requestWrapper.getMethod());
    Map<String, String[]> requestParams = requestWrapper.getParameterMap();

    String requestBody = IOUtils.toString(requestWrapper.getInputStream(),UTF_8);
    JsonNode requestJson = objectMapper.readTree(requestBody);

    RequestEntity<JsonNode> requestEntity = new RequestEntity<>(requestJson,requestHeaders, httpMethod, URI.create(requestUrl));
    LOGGER.info(appendFields(requestEntity),"Logging Http Request");


    HttpStatus responseStatus = HttpStatus.valueOf(responseWrapper.getStatusCode());
    HttpHeaders responseHeaders = new HttpHeaders();
    for (String headerName : responseWrapper.getHeaderNames()) {
      responseHeaders.add(headerName, responseWrapper.getHeader(headerName));
    }
    String responseBody = IOUtils.toString(responseWrapper.getContentInputStream(), UTF_8);
    JsonNode responseJson = objectMapper.readTree(responseBody);
    ResponseEntity<JsonNode> responseEntity = new ResponseEntity<>(responseJson,responseHeaders,responseStatus);
    LOGGER.info(appendFields(responseEntity),"Logging Http Response");
    responseWrapper.copyBodyToResponse();
  }
}

Answer 3

After couple of hours of struggling, I've finally found the solution.

In short, ContentCachingResponseWrapper.copyBodyToResponse() should be called in the end of the filter method.

ContentCachingResponseWrapper caches the response body by reading it from response output stream. So, the stream becomes empty. To write response back to the output stream ContentCachingResponseWrapper.copyBodyToResponse() should be used.