(Spring Boot) Filter를 통한 Request, Response Logging

Filter를 통한 Request, Response Logging 방식과 발생했던 문제

filter를 통한 request, response logging

개발을 하다 보면 요청된 Request에 대한 로깅이 필요한 경우가 생기는데요.

해당 포스팅은 'Filter를 통해 Request, Response에 대한 로깅을 남기는 방법과 그 과정에서 발생했던 문제점'에 대해 기록한 내용입니다.

 

***

Logging의 경우 Filter가 아닌 인터셉터(Interceptor) 또는 AOP(Aspect Oriented Programming)로도 처리가 가능한데요.

각각의 방식에 대한 용도와 장단점이 있겠지만, 여기서는 필터 체이닝 과정에서 ServletRequest, ServletResponse 객체에 대한 조작이 가능하다는 점과 스프링 영역 밖(Dispatcher Servlet 전후)에서 처리를 할 수 있다는 점 때문에 Filter에서 로깅 작업을 처리하게 되었습니다.

 

 

---

핵심은 요청 Body를 여러 번 읽을 수 없다는 것

Filter를 통한 Request, Response 로깅의 가장 큰 문제는 바로 요청의 본문 데이터를 한 번 밖에 읽을 수 없다는 것인데요.

 

request와 response의 본문(body)을 로깅하기 위해 HttpServletRequest의 getReader() 또는 getInputStream() 메서드를 호출하여 body를 읽는 경우, 다음 단계에서 body는 비어있는 상태가 됩니다.

이는 서블릿 구조상 생기는 문제로 서블릿은 요청, 응답 객체를 단 한 번만 읽을 수 있도록 설계되어 있기 때문입니다.

 

***

이러한 문제를 해결하기 위해 최초 HttpServletRequestWrapper를 상속받은 RequestWrapper라는 커스텀 클래스를 통한 방법으로 로깅을 시도했으나 form 요청(x-www-form-urlencoded, multipart-form)에 대해 Controller 단에서 데이터가 바인딩되지 않는 문제가 발생하였습니다.

 

이후 스프링 자체에서 요청의 body를 여러 번 읽을 수 있도록 구현해 놓은 ContentCachingRequestWrapper 객체를 통해 로깅을 시도하였고, json 요청과 x-www-form-urlencoded 요청에 대해서는 로깅 및 데이터 바인딩이 정상적으로 이루어졌지만, multipart-form 요처에 대해서는 body에 대한 로깅이 출력되지 않는 문제점이 발견되었습니다.

 

아래 이어지는 내용은 각각의 방식에 적용한 코드 및 상세 내용입니다.

 

* 내용 중 잘못된 부분이나 더 좋은 의견이 있으시면 댓글로 남겨주시면 감사드리겠습니다.

 

 

---

HttpServletRequestWrapper 클래스를 상속한 커스텀 클래스를 통한 방식

public class RequestWrapper extends HttpServletRequestWrapper {

    private byte[] cachedBody;

    public RequestWrapper(HttpServletRequest request) throws IOException {
        super(request);
        this.cachedBody = StreamUtils.copyToByteArray(request.getInputStream());
    }

    @Override
    public BufferedReader getReader() {
        return new BufferedReader(new InputStreamReader(new ByteArrayInputStream(this.cachedBody)));
    }

    @Override
    public ServletInputStream getInputStream() {
        final ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(cachedBody);

        return new ServletInputStream() {
            @Override
            public boolean isFinished() {
                return byteArrayInputStream.available() == 0;
            }

            @Override
            public boolean isReady() {
                return true;
            }

            @Override
            public void setReadListener(ReadListener readListener) {
                throw new UnsupportedOperationException();
            }

            @Override
            public int read() throws IOException {
                return byteArrayInputStream.read();
            }
        };
    }
}

(RequestWrapper Class)

 

RequestWrapper 클래스는 HttpServlerRequest를 감싸는 클래스로 생성자 호출 시 getInputStream() 메서드를 통해 InputStream의 내용을 byte 배열로 저장합니다.

이후 getInputStream() 호출 시 저장된 byte 배열을 통해 기존의 InputStream의 내용을 가져오는 방식입니다.

 

 

@Slf4j
@Component
public class LoggingFilterRequestWrapper extends OncePerRequestFilter {

  @Override
  protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
      throws ServletException, IOException {
    if (isAsyncDispatch(request)) {
      filterChain.doFilter(request, response);
    } else {
      doFilterWrapped(new RequestWrapper(request), new ContentCachingResponseWrapper(response), filterChain);
    }
  }

  protected void doFilterWrapped(RequestWrapper request, ContentCachingResponseWrapper response,
                                 FilterChain filterChain) throws IOException, ServletException {
    try {
      filterChain.doFilter(request, response);
      logRequest(request);
    } finally {
      logResponse(response);
      response.copyBodyToResponse();
    }
  }

  private static void logRequest(RequestWrapper request) throws IOException {
    String queryString = request.getQueryString();
    log.info("Request : {} uri=[{}] content-type[{}]", request.getMethod(),
        queryString == null ? request.getRequestURI() : request.getRequestURI() + queryString,
        request.getContentType());

    logPayload("Request", request.getContentType(), request.getInputStream());
  }

  private static void logResponse(ContentCachingResponseWrapper response) throws IOException {
    logPayload("Response", response.getContentType(), response.getContentInputStream());
  }

  private static void logPayload(String prefix, String contentType, InputStream inputStream) throws IOException {
    boolean visible = isVisible(MediaType.valueOf(contentType == null ? "application/json" : contentType));

    if (visible) {
      byte[] content = StreamUtils.copyToByteArray(inputStream);
      if (content.length > 0) {
        String contentString = new String(content);
        log.info("{} Payload: {}", prefix, contentString);
      }
    } else {
      log.info("{} Payload: Binary Content", prefix);
    }
  }

  private static boolean isVisible(MediaType mediaType) {
    final List<MediaType> VISIBLE_TYPES = Arrays.asList(
        MediaType.valueOf("text/*"),
        MediaType.APPLICATION_FORM_URLENCODED,
        MediaType.APPLICATION_JSON,
        MediaType.APPLICATION_XML,
        MediaType.valueOf("application/*+json"),
        MediaType.valueOf("application/*+xml"),
        MediaType.MULTIPART_FORM_DATA
    );

    return VISIBLE_TYPES.stream()
        .anyMatch(visibleType -> visibleType.includes(mediaType));
  }
}

(LoggingFilter Class)

 

해당 Filter의 경우 OncePerRequestFilter를 상속받았으며, doFilterInternal() 메서드 내부에서 HttpServletRequest 요청을 RequestWrapper 클래스로 감싸 doFilterWrapped() 메서드로 넘기고 doFilterWrapped() 메서드 내부적으로 로깅에서 요청에 대한 로깅을 출력하였습니다.

 

하지만 이 방식의 경우 json 요청의 경우 request body에 대한 로깅도 정상적으로 출력되고 Controller 단에서의 데이터 바인딩도 정상적으로 이루어졌지만, form 방식(x-www-form-urlencoded, multipart-form)에 대해서는 Controller 단에서 데이터 바인딩이 정상적으로 이루어지지 않는다는 문제점이 발견되었는데요.

 

 

public RequestWrapper(HttpServletRequest request) throws IOException {
    super(request);
    //추가된 부분
    Map<String, String[]> parameterMap = request.getParameterMap();
    this.cachedBody = StreamUtils.copyToByteArray(request.getInputStream());
}

(RequestWrapper 생성자)

 

RequestWrapper 클래스의 생성자에 request.getParameterMap() 메서드를 통한 다음 코드를 추가하게 되면 Controller 단에서의 데이터 바인딩이 정상적으로 이루어지지만, 대신 getParameterMap() 메서드에서 InputStream이 소모되기 때문인지 이후 바로 아래 request.getInputStream() 부분에서 빈 데이터를 가져오는 것이 확인되었습니다.

 

* getParameterMap() 메서드를 호출하는 방식 말고 getParameter 관련 메서드들을 override 하면 된다는 내용도 있었지만 데이터 바인딩에는 실패하였습니다.

 

결론적으로 해당 방식의 경우 json 요청에 대한 로깅에는 사용될 수 있으나 form 요청에 대해서는 사용할 수 없었습니다.

(이 문제에 대한 해결 방안이 있다면 댓글로 남겨 주시면 감사드리겠습니다.)

 

 

---

Spring에서 이미 구현된 ContentCachingRequestWrapper 클래스를 사용하는 방법

@Slf4j
@Component
public class LoggingFilterContentCachingRequestWrapper extends OncePerRequestFilter {

  @Override
  protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
      throws ServletException, IOException {
    if (isAsyncDispatch(request)) {
      filterChain.doFilter(request, response);
    } else {
      doFilterWrapped(new ContentCachingRequestWrapper(request), new ContentCachingResponseWrapper(response), filterChain);
    }
  }

  protected void doFilterWrapped(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response,
                                 FilterChain filterChain) throws IOException, ServletException {
    try {
      filterChain.doFilter(request, response);
      logRequest(request);
    } finally {
      logResponse(response);
      response.copyBodyToResponse();
    }
  }

  private static void logRequest(ContentCachingRequestWrapper request) throws IOException {
    String queryString = request.getQueryString();
    log.info("Request : {} uri=[{}] content-type[{}]", request.getMethod(),
        queryString == null ? request.getRequestURI() : request.getRequestURI() + queryString,
        request.getContentType());

    logPayload("Request", request.getContentType(), request.getContentAsByteArray());
  }

  private static void logResponse(ContentCachingResponseWrapper response) throws IOException {
    logPayload("Response", response.getContentType(), response.getContentAsByteArray());
  }

  private static void logPayload(String prefix, String contentType, byte[] rowData) throws IOException {
    boolean visible = isVisible(MediaType.valueOf(contentType == null ? "application/json" : contentType));

    if (visible) {
      if (rowData.length > 0) {
        String contentString = new String(rowData);
        log.info("{} Payload: {}", prefix, contentString);
      }
    } else {
      log.info("{} Payload: Binary Content", prefix);
    }
  }
}

(LoggingFilter Class)

 

Filter의 전체적인 내용은 같으며, 기존의 HttpServletRequest를 커스텀 클래스인 RequestWrapper로 감싸는 게 아니라 스프링에서 해당 목적을 위해 구현되어 있는 ContentCachingRequestWrapper 클래스로 감쌌다는 것이 차이점입니다.

 

그리고 logPayload() 메서드에서 InputStream 객체를 받는 것이 아니라 byte 배열을 받도록 수정되었으며, 이 과정에서는 ContentCachingRequestWrapper, ContentCachingResponseWrapper 클래스의 getContentAsByteArray() 메서드가 사용되었습니다.

 

해당 방식의 경우 따로 커스텀 객체를 생성하지 않아도 된다는 장점이 있는데요.

문제는 json, x-www-form-urlencoded 두 방식의 요청에 대해서는 요청 body에 대한 로깅과 Controller 단에서의 데이터 바인딩이 정상적으로 진행되지만 multipart-form 요청에서의 로깅이 안된다는 점이 있었습니다.

 

 

getParameter 관련 메서드

(getParameter 관련 메서드, getParameterNames() getParameterValues() 메서드 이미지 생략)

 

multipart-form 요청에 대한 로깅이 안 되는 부분은 ContentCachingRequestWrapper 클래스의 getParameter 관련 메서드들에서 찾을 수 있었는데요.

 

 

isFormPost() method

isFormPost() 메서드를 살펴보면 'MediaType.APPLICATION_FORM_URLENCODED_VALUE'에 대해서만 getParameter 관련 메서드가 동작하게 되어 있다는 것을 볼 수 있었습니다.

 

결국 억지로라도 multipart-form 요청에 대한 로깅을 남기고 싶은 경우 ContentCachingRequestWrapper와 동일하게 동작하는 Custom 클래스를 만들고 isFormPost() 메서드 부분에서 x-www-form-urlencoded 요청에 대한 것만 true로 반환하는 부분을 지워주면 됩니다.

(해당 내용에 대한 코드는 아래 github 링크를 참고하실 수 있습니다.)

 

 

---

Filter 단에서 Request, Response에 대한 로깅 처리 결론

결론적으로 로깅을 남기기 위해 시도했던 위 방식들 중 모든 요청에 대해 로깅 및 데이터 바인딩이 깔끔하게 진행되는 코드는 아직 구현하지 못했습니다.

이번 과정을 통해 Controller 단에서 데이터 바인딩이 되는 과정에 대해서도 조금 더 자세하게 찾아봐야겠다고 느끼게 되었으며, 위 문제를 해결할 수 있는 더 좋은 구현 방식을 찾게 된다면 추가로 포스팅하도록 하겠습니다.

 

 

 

< github source code >

https://github.com/JianChoi-Kor/filter-logging/tree/master/src/main/java/com/example/test/r1

 

 

< 참고 자료 >

https://www.baeldung.com/spring-reading-httpservletrequest-multiple-times

https://keichee.tistory.com/467

https://prohannah.tistory.com/182