요청 정보는 서비스 로직 시작 전에 찍어야지..?

저번 포스팅에 있던 내용과 이어질 듯..ㅎ

 

바로 이전 포스팅

2022.08.17 - [개발 이야기/Spring] - 아 인터셉터에서 Request Body 로그 찍고싶다..

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

여기서 보면 스프링 인터셉터의 afterCompletion에서 로그를 찍고 있다.

왜 afterCompletion에서 찍게 됐냐면 바로 RequestBody가 스트림 형태로 들어오기 때문.

스트림은 한번 소비하면 다시 못쓰기 때문에 로깅에서 써버리면 서비스 로직이 박살난다.

 

그래서 서비스 로직에서 일단 쓰게 하고 쓴 내용을 캐싱하는 클래스인 ContentCachingRequestWrapper로 request를 한번 포장해서 afterCompletion에서 캐싱된 값으로 로그를 찍었었다.

 

저걸 막 했을 당시엔 매우 만족스러웠는데, 시간이 지나고 보니 서비스로직 전부 수행된 뒤에 로그가 찍히는게 불편했다.

왜냐면 일단 순서상이 그렇다. 요청이 들어오고 서비스 로직이 실행된다.

근데 로그에는 서비스 로직이 실행되는 로그가 먼저 찍히고 그 다음에 어떤 요청이 들어와서 그 서비스 로직이 수행됐는 지 찍히는 건데 이거 너무 불편하다.

 

말로 옮겨 적으면 '~~ 실행됐다. ~~요청이 들어왔을 때' 이건데

무슨 영어문장 독해도 아니고 어순이 이상하잖아.

'~~요청이 들어와서, ~~ 실행됐다.' 이게 훨씬 자연스럽다고 느꼈다. 암튼 그래서 인터셉터에서 로그 찍긴 할건데 preHandle 메서드에서 찍도록 변경할 것이다.

 

근데 저번에 RequestBody preHandle에서 찍는거 실패했다며?

그건 저번이고, 이번엔 해결법을 찾았다. 원래 끝까지 가면 내가 다 이긴다.

자, 저번에 preHandle에서 로그를 찍지 않은 이유는 RequestBody 때문이다.

이걸 로깅에 먼저 써버리면 서비스 로직을 실행할 때 바디가 안들어가서 다 깨지는 게 문제인건데...

그걸 ContentCachingRequestWrapper로 저번엔 해결했었다. 서비스 로직에서 일단 쓰게 하고 ContentCachingRequestWrapper에 캐싱된 내용으로 로깅을 찍었었음.

 

그럼 ContentCachingRequestWrapper의 캐싱 기능을 이용해서 첫 바디 스트림을 읽을 땐 그냥 원래대로 읽게 해주고 두번 째 읽을 땐 캐시된 내용을 읽도록 새로운 구현체를 만들어낸다면? ㅎㅅㅎ

 

바로 코드 구현 함 보자

public class CustomCachingRequestWrapper extends ContentCachingRequestWrapper {

    private boolean used = false;

    public CustomCachingRequestWrapper(final HttpServletRequest request) {
        super(request);
        this.setCharacterEncoding(StandardCharsets.UTF_8.name());
    }

    //...

    @Override
    public ServletInputStream getInputStream() throws IOException {
        if (used) {
            return new CustomServletInputStream(super.getContentAsByteArray());
        }
        used = true;
        return super.getInputStream();
    }

    static class CustomServletInputStream extends ServletInputStream {

        private final InputStream inputStream;

        public CustomServletInputStream(final byte[] content) {
            this.inputStream = new ByteArrayInputStream(content);
        }

        //...
    }
}

핵심 코드만 뽑아봤다. ContentCachingRequestWrapper를 상속받아서 커스텀 RequestWrapper를 만든다.
그리고 used라는 상태를 둘건데, 바디를 한번 읽었는 지 한번도 안읽었는 지를 구분하기 위해 썼다.

한번도 안읽었으면 true로 변경해주고 원래대로 InputStream을 리턴한다.

 

만약 한번이라도 읽었으면 캐싱된 값을 읽어오는 getContentAsByteArray() 메서드로 새로운 InputStream을 만들어서 반환해준다.

이렇게 해두면 로그를 찍을 땐 처음 읽으니까 원래대로 동작하고, 이후에 서비스 로직에서 바디를 필요로 할 땐 캐싱된 내용으로 새로 스트림을 만들어서 가져가서 동작하게 된다.

 

그럼 이제 preHandle로 옮겨보자

@Override
public boolean preHandle(final HttpServletRequest request, final HttpServletResponse response, final Object handler)
        throws Exception {
    final CustomCachingRequestWrapper cachingRequest;
    try {
        cachingRequest = (CustomCachingRequestWrapper) request;
    } catch (final ClassCastException e) {
        log.info("로깅 필터가 동작했는지 확인해주세요.");
        return true;
    }

    log.info(
            LogForm.SUCCESS_REQUEST_FORM,
            request.getMethod(),
            request.getRequestURI(),
            StringUtils.hasText(request.getHeader(HttpHeaders.AUTHORIZATION)),
            new String(cachingRequest.getInputStream().readAllBytes())
    );

    return true;
}

머 이런 코드가 완성됐다. 다음 할 일은 파라미터 갯수 2개 이하로 줄여보기랑 CustomCachingRequestWrapper 리팩터링..

이번에 너무 가라로 구현한 느낌이다.

 

사실 꼭 ContentCachingRequestWrapper를 상속받지 않아도 되고 그냥 HttpServletRequest 인터페이스를 구현만 하면 된다. 난 그냥 쟤가 캐싱하는 기능이 있어서 그걸 직접 구현하지 않고 가져다 쓰고싶어서 상속했을 뿐...

근데 짜다보니 원래 있던 클래스를 상속해서 쓰는거 은근 신경쓸 게 있는 것 같아서 다시 리팩토링 한다면 직접구현 할 예정이다.

캐싱을 두고 매번 새 스트림을 생성해주는데 성능상 문제는 없을 지... ServletInputStream을 구현해줘야 하는데 어떤 방식으로 구현해야하는 지.. 등등..

 

뭐 아직까지 딱히 문제가 되진 않았지만.. ServletInputStream을 상속하는 CustomServletInputStream을 만들어야 했는데, 얘 구현 메서드들 보면 그냥 바디가 없다고 보면 된다... abstract 메서드들이라 어떻게 구현해야할 지 모르겠더라.. 문서를 좀 찾아보면서 할걸 그랬나.. 암튼 로깅 리팩토링은 다시 한번 해야하는데 그 때 건드려볼 예정.