<div id="readability-page-1" class="page"><div><img src="https://velog.velcdn.com/images/0_0_yoon/post/eca7bdcf-ed2b-42b8-8752-981436b62041/image.png">
<h3 id="문제상황">문제상황</h3>
인터셉터에서 로깅 할 때 Requset, Response 의 Body 가 출력되지 않았다.
<pre><code>	@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);
 }</code></pre>
<h3 id="원인">원인</h3>
먼저 ContentCachingRequestWrapper, ContentCachingResponseWrapper 를 사용한 이유는 요청, 응답의 본문 내용(InputStream, OutputStream)을 읽고 쓰게 되면 그 내용들을 다시 읽어올 수 없기 때문이다.
문제 원인의 첫 번째는 Request Body 가 캐싱 되기 전에 사용한 점이다. ContentCachingRequestWrapper 는 Request Body 가 읽혔을 때 캐싱 된다. 문제상황 코드를 기준으로 캐싱 되는 시점은 인터셉터를 거친 후 ArgumentResolver 의 MessegeConverter(MappingJackson2HttpMessageConverter) 에서 Request Body 가 읽혔을 때이다.
<blockquote>
이 클래스는 콘텐츠를 읽을 때만 캐시하는 인터셉터 역할을 하지만 그렇지 않으면 콘텐츠를 읽지 않습니다. 즉, 요청 콘텐츠가 사용되지 않으면 콘텐츠가 캐시되지 않으며 getContentAsByteArray() 를 통해 검색할 수 없습니다. 
ContentCachingRequestWrapper API 문서
</blockquote>
왜 생성할 때 캐싱 되도록 구현하지 않고 위와 같이 구현한 걸까? 
Spring 은 요청을 처리하는 계약된 절차를 가지고 있는데 캐싱 된 내용을 가져오는 기능은 매우 구체적이며(구체 클래스의 메서드) Spring 과 계약되지 않은 부분이기 때문이라고 생각한다.
두 번째 원인은 이미 응답한 뒤에 ContentCachingResponseWrapper 를 사용한 점이다. 
쥐도 새도 모르게 언제 응답 된 걸까? 
ReturnValueHandler 의 MessageConverter(MappingJackson2HttpMessageConverter) writeInternal 메서드가 호출될 때 응답된다.
<h3 id="해결">해결</h3>
첫 번째 원인을 해결하기 위해서는 ArgumentResolver 의 MessegeConverter 에 실제 요청이 아닌 ContentCachingRequestWrapper 를 넘겨줘야 한다. DispatcherServlet 이 전달 받는 요청 객체를 ContentCachingRequestWrapper 로 바꿔치기해야 하는데 인터셉터에서는 할 수 없다.(인터셉터에서는 단지 인자로 넘겨받기만 한다) 
반면 필터는 필터 체인에 의해서 순서대로 동작하며 이때 호출하는 곳에서 요청, 응답 객체를 넘겨받기 때문에 다음에 사용될 요청, 응답 객체를 교체할 수 있다. 
두 번째 원인 또한 응답 객체도 필터에서 ContentCachingResponseWrapper 로 교체함으로써 해결할 수 있다.
<pre><code>@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();
 }
 // 생략
}</code></pre>
교체된 ContentCachingResponseWrapper 는 Inner Class 로 ServletOutputStream 를 구현한 ResponseServletOutputStream 을 가지고 있다. 이 ResponseServletOutputStream 이 ReturnValueHandler 의 MessageConverter(MappingJackson2HttpMessageConverter) 에서 응답 본문을 캐싱하도록 동작한다.(원래라면 이때 클라이언트로 응답이 전송된다) 그래서 copyBodyToResponse 메서드를 호출해서 캐싱 된 본문(직렬화된 상태)을 실제 클라이언트에게 응답한다.
<blockquote>
캐시된 본문 콘텐츠를 응답에 복사합니다. 
ContentCachingResponseWrapper 의 copyBodyToResponse 메서드 
</blockquote></div></div>

0_0_yoon.log

yoon

문제상황
인터셉터에서 로깅 할 때 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 메서드

ContentCachingRequestWrapper, ContentCachingResponseWrapper

댓글

ContentCachingRequestWrapper, ContentCachingResponseWrapper