ServletInputStream은 1회용

아마도 Spring boot 환경에서 Request, Response Logging을 하기 위해 Google 검색을 한다면 대부분의 글에서 InputStream은 1번만 읽을 수 있으니 이미 캐싱 기능이 만들어져있는 ContentCachingRequestWrapper를 사용하거나 HttpServletRequestWrapper를 상속해서 직접 캐싱 기능을 구현하는 방법이 나올 것이다.

처음에 Logging을 구현할 때는 HttpServletRequestWrapper를 상속해서 구현했었는데 좀 찾아보니 ContentCachingRequestWrapper를 사용해도 충분할 것 같다는 생각이 들었기에 ContentCachingRequestWrapper를 적용하는 과정을 남겨본다.

ContentCachingRequestWrapper

위 코드 사진은 ContentCachingRequestWrapper 클래스이다. Spring에서도 Servlet의 InputStream은 특성상 한번 읽으면 다시 읽을 수 없다는 점을 인지해 InputStream을 재사용 할 수 있도록 만들어 둔 것 같다. 멤버 변수를 보면 cachedContent가 있다.
그래서 나는 무작정 사용해보았다.

ContentCachingRequestWrapper내부를 보면 getContentAsByteArray함수가 있는데 캐시 된 Request Inputstream을 준다는 내용 같다.

@Component
public class ContentCachingFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
        ContentCachingRequestWrapper contentCachingRequestWrapper = new ContentCachingRequestWrapper(request);
        System.out.println("In filter");
        System.out.println(new String(contentCachingRequestWrapper.getContentAsByteArray()));
        filterChain.doFilter(contentCachingRequestWrapper, response);
    }
}

Interceptor에서 구현을 하던 Filter에서 구현을 하던 이것은 본인의 선택이다. 나는 Client의 요청으로부터 제일 가까이 있는 Filter를 선택했다.
아무튼 Filter에서 사용해보자. 위 코드처럼 ContentCachingRequestWrapper를 사용해서 데이터를 출력해보도록 하였다.

    @Getter
    @Setter
    public static class PostBoardRequest {
        private String title;
        private String content;

        @Override
        public String toString() {
            return "PostBoardRequest{" +
                "title='" + title + '\'' +
                ", content='" + content + '\'' +
                '}';
        }
    }

    @PostMapping("")
    public ResponseEntity<String> postBoard(@RequestBody PostBoardRequest postBoardRequest) {
        System.out.println(postBoardRequest.toString());
        return ResponseEntity.status(200).body("123");
    }       

간단하게 위처럼 PostBardRequest를 요청받는 컨트롤러이다.

확인을 해보면 컨트롤러에서 호출하는 println만 보일 뿐 filter에서 데이터는 공백으로 되어있다.
bytearray가 잘못 사용된 것일까 싶어서 byte배열의 길이를 출력시켜 보았다.

음 캐싱된 데이터 길이가 0으로 찍힌다. 한마디로 캐싱이 되지 않았다.

ContentCachingRequestWrapper는 한번 읽혀야...

캐싱이 되지 않아 이것저것 해보다가 ContentCachingRequestWrapper클래스의 getContentAsByteArray함수를 다시 보았다.

캐시된 요청 내용을 바이트 배열로 반환합니다.
반환되는 배열은 콘텐츠 캐시 제한보다 클 수 없습니다.
참고: 이 메서드에서 반환되는 바이트 배열은 호출된 시점에 읽혀진 내용의 양을 반영합니다. 응용 프로그램이 내용을 읽지 않으면 이 메서드는 빈 배열을 반환합니다.

그렇다. 번역을 해본 결과, 그리고 직접 ContentCachingRequestWrapper는 클래스에서 사용되는 구현체를 보니 read되는 시점에 읽은 만큼 캐싱이 된다. 한마디로 한번 stream을 소비해야 캐싱이 된다.
따라서 캐싱 데이터 길이가 0으로 찍힌 이유는 아직 inputStream이 읽히지 않은 시점이기 때문이다.

보통 Post의 Request Dto의 InputStream이 사용되는 시점은 Http 데이터를 @RequestBody로 매핑시켜줄 때 일것이다.
매핑 과정을 공부하지 않았지만 HandlerMethodArgumentResolver <-> HttpMessageConverter 과정에서 사용되지 않을까 싶다.

아무튼 그렇다면 어떻게 사용해야 할까?

doFilter 이후에 response 과정에서 사용하기

@Component
public class ContentCachingFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
        ContentCachingRequestWrapper contentCachingRequestWrapper = new ContentCachingRequestWrapper(request);
        filterChain.doFilter(contentCachingRequestWrapper, response);
        System.out.println("after doFilter");
        System.out.println(new String(contentCachingRequestWrapper.getContentAsByteArray()));
    }
}

위 코드처럼 filterChain의 doFilter 메소드 호출 전이 아닌, doFilter 메소드 호출 이후 시점은 response를 후처리하는 시점일 것이기에 적어도 정상적이라면 호출이 되었을 것이다.

예상대로 한번 inputStream이 소비되었기에 캐싱이 되어 잘 출력이 된다. 여기서 의문이 들었다. 만약 컨트롤러에서 Response를 주기 전에 예외가 발생한다면 Filter가 과연 처리되는가이다.

Exception 예외 발생 시 doFilter?

    @PostMapping("")
    public ResponseEntity<String> postBoard(@RequestBody PostBoardRequest postBoardRequest) {
        throw new RuntimeException("exception");
    }

@Component
public class ContentCachingFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
        ContentCachingRequestWrapper contentCachingRequestWrapper = new ContentCachingRequestWrapper(request);
        System.out.println("before doFilter");
        filterChain.doFilter(contentCachingRequestWrapper, response);
        System.out.println("after doFilter");
        System.out.println(new String(contentCachingRequestWrapper.getContentAsByteArray()));
    }
}

위 코드처럼 컨트롤러 내에서 비즈니스 로직을 호출하였을 때 중간에 exception이 발생했다는 가정을 해보자.

위처럼 컨트롤러 내에서 예외가 발생한다면 doFilter 이후에 메소드는 실행되지 않기에 어떠한 요청이 예외가 발생한다면 그 요청의 로깅은 불가능하다는 것이다.

예외가 발생했을 때의 Logging이 더 중요하다는 생각에 doFilter 호출 이후의 로깅 처리는 선택지에서 제외해야 할 것 같다.
그럼 결론은 일단 ContentCachingRequestWrapper를 사용한다면 Filter에서 로깅은 불가능하다는 판단이 되었다.

Logging in Interceptor

결국 ContentCachingRequestWrapper를 사용한다면 interceptor에서 처리하는 것이 좋아보인다.
따라서 filter에서는 HttpServletRequest를 ContentCachingRequestWrapper로 변환해주는 역할을 하고 실질적인 logging은 interceptor에서 처리하는 방식으로 가보았다.

Spring의 HandlerInterceptor를 구현하여 사용해보았다.

HandlerInterceptor는 위와 같이 3개를 선택적으로 구현하면 되는데

preHandle -> handler 호출 전 (대략 컨트롤러 호출 전)
postHandle -> handler 호출 성공 후 (대략 뷰 렌더링 전)
afterCompletion -> 뷰 렌더링 후

호출 되는 시점이 위와 같다.

preHandle은 컨트롤러를 호출 하기 전이기에 아직 inputStream이 소비 되지 않아 캐싱이 안된 시점이라 사용 불가능.
postHandle은 예외가 발생하면 호출하지 않아 사용 불가능
afterCompletion은 예외가 발생한다면 4번째 인자로 어떤 예외가 발생하는지 전달되며 호출이 되기에 적합하다고 판단했다.

public class LoggingInterceptor implements HandlerInterceptor {
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
        @Nullable Exception ex) throws Exception {
        ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;
        System.out.println("Interceptor");
        System.out.println(new String(cachingRequest.getContentAsByteArray()));
    }
}

// ---------------------- //

@Configuration
public class InterceptorConfig implements WebMvcConfigurer {
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LoggingInterceptor());
    }
}

위와 같이 interceptor를 작성하고 추가하였다.

일단 위 사진처럼 Interceptor내에서 캐싱된 inputStream이 잘 출력됨을 확인하였다. 그리고 정말 예외 발생 시에도 출력이 가능한지 확인해보았다.

위 사진을 보면 알 수 있듯이 interceptor의 afterCompletion가 호출된 후 예외가 발생됨을 볼 수 있다. 따라서 예외가 발생해도 logging은 가능하나 afterCompletion이 두번 호출되는 것을 볼 수 있다. 나는 원인을 찾아보기 시작했다.

public class LoggingInterceptor implements HandlerInterceptor {
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
        @Nullable Exception ex) throws Exception {
        System.out.println("Interceptor");
        System.out.println(request.getRequestURI());
        ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;
        System.out.println(new String(cachingRequest.getContentAsByteArray()));
    }
}

interceptor의 코드를 위처럼 수정 하고 2번째의 요청 url을 보면 알 수 있다.

컨트롤러에서 RuntimeException을 던지고 핸들링을 따로 해주지 않았다. 따라서 Spring에서는 오류 발생시 /error 페이지로 이동시켜줘야 하고
/error 페이지의 렌더링 후 실행된 afterCompletion이였다.
아마 대부분 Spring boot를 사용하는 개발자라면 @ControllerAdvice등을 통해서 예외를 전역으로 처리하거나 핸들링 할 것이기에 문제는 없겠지만
지금 상태에서 해결하고자 한다면

@Configuration
public class InterceptorConfig implements WebMvcConfigurer {
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new LoggingInterceptor())
            .excludePathPatterns("/error");
    }
}

위 처럼 /error 페이지에서는 interceptor가 동작되지 않도록 수정하면 된다.

그럼 interceptor는 1번만 동작하게 된다.

public class LoggingInterceptor implements HandlerInterceptor {
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
        @Nullable Exception ex) throws Exception {
        ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;
        logging(cachingRequest);
    }
}

로깅방식은 각자 구현하기 나름이기에 로깅에 대해서는 구체적으로 구현하는 것은 나중에 제대로 해보기로 하였다.