ContentCachingRequestWrapper, ContentCachingResponseWrapper

문제상황

인터셉터에서 로깅 할 때 Requset, Response 의 Body 가 출력되지 않았다.

	@Override
    public boolean preHandle(final HttpServletRequest request, final HttpServletResponse response, final Object handler) {
        apiTimer.start();
        
        final String body = new String(new ContentCachingRequestWrapper(request).getContentAsByteArray());
        log.info(REQUEST_LOG_FORMAT, request.getMethod(), request.getRequestURI(), request.getHeader("Authorization"),
                body);
        return true;
   	}
    
    @Override
    public void afterCompletion(final HttpServletRequest request, final HttpServletResponse response, final Object handler, final Exception ex) {
        apiTimer.stop();
        
        final ContentCachingResponseWrapper contentCachingResponseWrapper = new ContentCachingResponseWrapper(response);
        final String responseBody = new String(contentCachingResponseWrapper.getContentAsByteArray());
        final int queryCount = apiQueryCounter.getCount();
        log.info(RESPONSE_LOG_FORMAT, response.getStatus(), request.getMethod(), request.getRequestURI(),
                queryCount, apiTimer.getLastTaskTimeMillis(), responseBody);
    }

원인

먼저 ContentCachingRequestWrapper, ContentCachingResponseWrapper 를 사용한 이유는 요청, 응답의 본문 내용(InputStream, OutputStream)을 읽고 쓰게 되면 그 내용들을 다시 읽어올 수 없기 때문이다.

문제 원인의 첫 번째는 Request Body 가 캐싱 되기 전에 사용한 점이다. ContentCachingRequestWrapper 는 Request Body 가 읽혔을 때 캐싱 된다. 문제상황 코드를 기준으로 캐싱 되는 시점은 인터셉터를 거친 후 ArgumentResolver 의 MessegeConverter(MappingJackson2HttpMessageConverter) 에서 Request Body 가 읽혔을 때이다.

이 클래스는 콘텐츠를 읽을 때만 캐시하는 인터셉터 역할을 하지만 그렇지 않으면 콘텐츠를 읽지 않습니다. 즉, 요청 콘텐츠가 사용되지 않으면 콘텐츠가 캐시되지 않으며 getContentAsByteArray() 를 통해 검색할 수 없습니다.
ContentCachingRequestWrapper API 문서

왜 생성할 때 캐싱 되도록 구현하지 않고 위와 같이 구현한 걸까?
Spring 은 요청을 처리하는 계약된 절차를 가지고 있는데 캐싱 된 내용을 가져오는 기능은 매우 구체적이며(구체 클래스의 메서드) Spring 과 계약되지 않은 부분이기 때문이라고 생각한다.

두 번째 원인은 이미 응답한 뒤에 ContentCachingResponseWrapper 를 사용한 점이다.
쥐도 새도 모르게 언제 응답 된 걸까?
ReturnValueHandler 의 MessageConverter(MappingJackson2HttpMessageConverter) writeInternal 메서드가 호출될 때 응답된다.

해결

첫 번째 원인을 해결하기 위해서는 ArgumentResolver 의 MessegeConverter 에 실제 요청이 아닌 ContentCachingRequestWrapper 를 넘겨줘야 한다. DispatcherServlet 이 전달 받는 요청 객체를 ContentCachingRequestWrapper 로 바꿔치기해야 하는데 인터셉터에서는 할 수 없다.(인터셉터에서는 단지 인자로 넘겨받기만 한다)
반면 필터는 필터 체인에 의해서 순서대로 동작하며 이때 호출하는 곳에서 요청, 응답 객체를 넘겨받기 때문에 다음에 사용될 요청, 응답 객체를 교체할 수 있다.
두 번째 원인 또한 응답 객체도 필터에서 ContentCachingResponseWrapper 로 교체함으로써 해결할 수 있다.

@Slf4j
@Component
public class LoggingFilter extends OncePerRequestFilter {

   @Override
   protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response, final FilterChain filterChain)
            throws ServletException, IOException {
        final ContentCachingRequestWrapper cachingRequest = new ContentCachingRequestWrapper(request);
        final ContentCachingResponseWrapper cachingResponse = new ContentCachingResponseWrapper(response);
        apiTimer.start();
        filterChain.doFilter(cachingRequest, cachingResponse);
        apiTimer.stop();
        logRequestAndResponse(cachingRequest, cachingResponse);
        cachingResponse.copyBodyToResponse();
   }
        // 생략
}

교체된 ContentCachingResponseWrapper 는 Inner Class 로 ServletOutputStream 를 구현한 ResponseServletOutputStream 을 가지고 있다. 이 ResponseServletOutputStream 이 ReturnValueHandler 의 MessageConverter(MappingJackson2HttpMessageConverter) 에서 응답 본문을 캐싱하도록 동작한다.(원래라면 이때 클라이언트로 응답이 전송된다) 그래서 copyBodyToResponse 메서드를 호출해서 캐싱 된 본문(직렬화된 상태)을 실제 클라이언트에게 응답한다.

캐시된 본문 콘텐츠를 응답에 복사합니다.
ContentCachingResponseWrapper 의 copyBodyToResponse 메서드