알고 쓰자 - ContentCachingRequestWrapper

ServletInputStream은 1회용

Spring boot 환경에서 Request, Response Logging을 하기 위해 Google 검색을 한다면 대부분의 글에서

InputStream은 1번만 읽을 수 있으니 이미 캐싱 기능이 만들어져있는 ContentCachingRequestWrapper를 사용하거나 HttpServletRequestWrapper를 상속해서 직접 캐싱 기능을 구현하는 방법이 나옵니다.

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

적용하는 과정을 남기게 되었습니다.

ContentCachingRequestWrapper

 

위 코드는 Spring에서 제공하는 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에서 처리를 하기로 하였습니다.
테스트를 위해 위 코드처럼 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에서의 println은 공백 (빈 문자열)이 출력되고 있습니다. 

 

bytearray가 잘못 사용된 것일까 싶어서 byte배열의 길이를 출력시켜 보았습니다. 

길이는 0으로 캐싱이 되지 않았다고 예상할 수 있습니다.

ContentCachingRequestWrapper는 한번 읽혀야...

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

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

 

설명을 다시 읽어보니 inputStream이 읽히는 시점에 cachedContent에 캐싱 된 데이터가 적재되는 것이였습니다.

 

 

ContentCachingRequestWrapper 구현체를 확인해보면 read되는 시점에 읽은 만큼 캐싱이 처리됨을 볼 수 있었습니다.

따라서 filter에서 캐싱 데이터 길이가 0으로 찍힌 이유는 아직 inputStream이 읽히지 않은 시점이기 때문입니다.

ContentCachingRequestWrapper를 이용하여 Request와 Response를 로깅을 하기 위해선 Spring이 InputStream을

Read 한 이후여야 합니다. 

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 메소드 호출 이후는 이미 요청을 처리한 시점이기 때문에 Spring 내부적으로

Request InputStream을 소비한 이후 일것입니다.

 

예상대로 한번 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의 코드를 위처럼 수정해서 요청의 URL을 확인해보았습니다.

 

테스트를 위해 작성 된 컨트롤러이기 때문에 RuntimeException을 던지고 핸들링을 따로 해주지 않았습니다.

Spring에서는 오류 발생시 /error 페이지로 이동시켜줘야 하고 /error 페이지의 렌더링 후 실행된 afterCompletion이였습니다.
대부분 Spring boot 환경에서는 @ControllerAdvice등을 통해서 예외를 전역으로 처리하거나 핸들링 할 것이기에 문제는 없을 것입니다.