ContentCachingResponseWrapper Produces Empty Response

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

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.

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.