아 인터셉터에서 Request Body 로그 찍고싶다..

요즘 우테코 레벨3과정의 팀 프로젝트를 하고 있다. 팀원끼리 업무 나눠서 분업하고 있는데 로깅을 맡게 되었다.

로깅 전략을 세우다 보니 모든 Http 요청에 대한 정보를 찍을 필요성을 느꼈다.

모든 요청에 대한 공통 처리이니 '아 스프링의 인터셉터에서 로그 찍음 되겠네!' 싶었다.

 

찍고싶은 요청 정보는 HTTP Method, Request URI, AccessToken 존재 여부, Request Body 정도였다.

Interceptor는 preHandle이라는 메서드에서 파라미터로 HttpServletRequest 가 들어오고 여기서 요청 정보를 뽑을 계획이었다.

그래서 짠 코드

@Slf4j
@Component
@RequiredArgsConstructor
public class LoggingInterceptor implements HandlerInterceptor {

    private final ObjectMapper objectMapper;

    @Override
    public boolean preHandle(final HttpServletRequest request, final HttpServletResponse response, final Object handler)
            throws Exception {
        final ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;

        log.info(
                "\n HTTP Method : {} " +
                "\n Request URI : {} " +
                "\n AccessToken Exist : {} " +
                "\n Request Body : {}",
                request.getMethod(),
                request.getRequestURI(),
                StringUtils.hasText(request.getHeader(HttpHeaders.AUTHORIZATION)),
                objectMapper.readTree(cachingRequest.getInputStream().readAllBytes()) // 얘가 문제...
        );

        return true;
    }
}

 

 

로그 찍힘 ㅋ

아 일단 로그 찍힌다. 근데 테스트의 상태가?

다 터짐 ㅋ

다 터진다..

치명적인 문제가 있었다. HttpServletRequest에서 Request Body를 가져올 때 InputStream에서 읽어왔는데,

컨트롤러의 핸들러 매핑 메서드의 파라미터에 @RequestBody 바인딩 될 때도 InputStream에서 읽어온다.

근데 스트림은 한번 읽으면 소비되기 때문에 Interceptor에서 로그 좀 찍자고 먼저 소비해버리면 컨트롤러의 핸들러 메서드에서 바디를 파라미터로 받을 수가 없다 ㅠㅠㅠㅠ

 

아 그럼 Request Body는 한 번밖에 못쓴다는 건가...
만약 그렇다면, Request Body를 찍으려면 핸들러 메서드마다 한줄씩 바인딩된 객체를 찍는 코드를 써야하나..

하는 개발자로서의 신념에 위해를 가하는 생각을 뒤로한 채 구글링을 해보았다.

InputStream을 캐싱할 수 있는 'ContentCachingRequestWrapper'라는 클래스로 HttpServletRequest를 포장하면 사용한 바디를 캐싱해두고 불러오는 메서드가 있단다.

 

포장 방법은 Filter를 추가해서 포장한 클래스로 바꾸는 것.

그래서 포장한 코드

@Component
@RequiredArgsConstructor
public class RequestBodyWrappingFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(
            final HttpServletRequest request,
            final HttpServletResponse response,
            final FilterChain filterChain
    ) throws ServletException, IOException {

        final ContentCachingRequestWrapper wrappingRequest = new ContentCachingRequestWrapper(request);
        filterChain.doFilter(wrappingRequest, response);
    }
}

머 이렇게 필터 추가해서 ContentCachingRequestWrapper로 바꿔서 다음 레이어로 넘겼다. (인터셉터는 필터가 다 돈 이후에 돈다.)

 

그다음 다시 인터셉터에서

@Slf4j
@Component
@RequiredArgsConstructor
public class LoggingInterceptor implements HandlerInterceptor {

    private final ObjectMapper objectMapper;

    @Override
    public boolean preHandle(
            final HttpServletRequest request,
            final HttpServletResponse response,
            final Object handler
    ) throws Exception {
        final ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;

        log.info(
                "\n HTTP Method : {} " +
                "\n Request URI : {} " +
                "\n AccessToken Exist : {} " +
                "\n Request Body : {}",
                request.getMethod(),
                request.getRequestURI(),
                StringUtils.hasText(request.getHeader(HttpHeaders.AUTHORIZATION)),
                objectMapper.readTree(cachingRequest.getContentAsByteArray())
        );
        
        return true;
    }
}

이렇게 짰다. 근데 바디가 빈 값이 찍힌다.

아 왜 안찍혀

 

이거 왜이래..? 하면서 또 구글링을 돌렸다.

ㅋㅋㅋ 이런거 발견

 

세줄 요약하면

1. ContentCachingRequestWrapper는 인풋 스트림 캐싱해서 여러 번 쓰게할 수 있는 애임.
2. getContentAsByteArray()메서드로 캐싱된걸 읽어올 수 있음.
3. 근데 InputStream을 써야 그때 캐싱되고 그걸 getContentAsByteArray()로 읽어오는 거임.

이렇다.

그래서 아 @RequestBody 에서 바인딩 다 되고 나면 getContentAsByteArray()에서 찍히겠구나 싶었다.

암튼 그래서 preHandle 말고 afterCompletion에서 찍기로 했다^^

@Slf4j
@Component
@RequiredArgsConstructor
public class LoggingInterceptor implements HandlerInterceptor {

    private final ObjectMapper objectMapper;

    @Override
    public void afterCompletion(
            final HttpServletRequest request,
            final HttpServletResponse response,
            final Object handler,
            final Exception ex
    ) throws Exception {
        final ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;

        log.info(
                "\n HTTP Method : {} " +
                "\n Request URI : {} " +
                "\n AccessToken Exist : {} " +
                "\n Request Body : {}",
                request.getMethod(),
                request.getRequestURI(),
                StringUtils.hasText(request.getHeader(HttpHeaders.AUTHORIZATION)),
                objectMapper.readTree(cachingRequest.getContentAsByteArray())
        );
    }
}

 

처리가 다 끝난 이후에 찍히는게 좀 거슬리긴 한데 뭐 이후에 찍힌다는걸 알고 보면 잘 읽힌다.

어차피 로그를 검색해서 볼 땐 찍힌 스레드를 command + F 로 검색해서 본다.

 

직접 RequestServletWrapper를 구현해서 캐싱하면 preHandle로도 찍을 수 있다는데 먼가 있는 클래스 쓰고 싶었다.

사실 귀찮았다....ㅋㅋㅋㅋ

 

암튼 로깅 끝^^👊