Spring Boot 에서 모든 원본 Http request 와 response 에 대한 log 를 기록하려고 한다.

요청 → Filter → Interceptor → AOP → Interceptor → Filter → 응답 의 처리 순서로 볼 때, 가장 원시적인 요청 본문과 응답 본문을 캐치할 수 있는 부분은 Filter 였다. 요청을 받자마자 Filter 에서 본문을 로깅하고, 응답 직전에 본문을 로깅하고... 하지만 이거슨 순수한 나만의 착각?

Request / Response body 로깅 목표와... 결과

• 비정상 요청 파악 및 비정상 응답 파악하기.
• 최대한 원시 본문을 유지할 것. (의미를 찾지못함;)
• 요청 본문과 응답 본문의 로깅을 각각 처리. (막상 분리하고 나니 굳이...)
• POST 메소드만 처리.
• form-urlencoded 와 application/json 모두 처리.
• 로깅 위치는 Filter 와 Interceptor 의 preHandle 과 afterCompletion 를 적절히 사용.

1. request / response 본문(body) 읽기

request 와 response 의 본문(body) 를 로깅하기 위해 HttpServletRequest 의 getReader() 나 getInputStream() 등을 통해서 읽어낼 경우, 다음 단계에서 이 본문들은 비어있는 상태가 된다. 인터셉터에서 request 본문을 읽는다면 컨트롤러에 파라미터가 전달되지 않을 것이고, 인터셉터에서 response 본문을 읽는다면 클라이언트에 내용이 빈 상태로 응답될 수 있다. 이를 방지하기 위해 사용하는 방법이 여러가지 있는데 난 그 중에서 ContentCachingRequestWrapper / ContentCachingResponseWrapper 클래스를 선택했다.

2. ContentCachingRequestWrapper / ContentCachingResponseWrapper

ContentCachingRequestWrapper 는 getReader() 나 getInputStream() 등을 통해서 읽은 요청 본문을 캐시하고 byte array 로 이를 읽을 수 있게 하는 HttpServletRequest 래퍼이다. ContentCachingResponseWrapper의 경우 Body를 돌려주기 위해 copyBodyToResponse method를 호출해줘야 한다.

아래는 filter 파일 하나에 전부 때려넣은 예제이다.

@Component
public class LoggingFilter implements Filter {

    private final Logger logger = LoggerFactory.getLogger(this.getClass());

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain)
            throws IOException, ServletException {

        if (servletRequest instanceof HttpServletRequest && servletResponse instanceof HttpServletResponse) {
            HttpServletRequest request = (HttpServletRequest) servletRequest;
            HttpServletResponse response = (HttpServletResponse) servletResponse;

            HttpServletRequest requestToCache = new ContentCachingRequestWrapper(request);
            HttpServletResponse responseToCache = new ContentCachingResponseWrapper(response);

            chain.doFilter(requestToCache, responseToCache);

            logger.info("request header: {}", getHeaders(requestToCache));
            logger.info("request body: {}", getRequestBody((ContentCachingRequestWrapper) requestToCache));
            logger.info("response body: {}", getResponseBody(responseToCache));
           
        } else {
            chain.doFilter(servletRequest, servletResponse);
        }
    }

    private Map<String, Object> getHeaders(HttpServletRequest request) {
        Map<String, Object> headerMap = new HashMap<>();

        Enumeration<String> headerArray = request.getHeaderNames();
        while (headerArray.hasMoreElements()) {
            String headerName = headerArray.nextElement();
            headerMap.put(headerName, request.getHeader(headerName));
        }
        return headerMap;
    }

    private String getRequestBody(ContentCachingRequestWrapper request) {
        ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
        if (wrapper != null) {
            byte[] buf = wrapper.getContentAsByteArray();
            if (buf.length > 0) {
                try {
                    return new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
                } catch (UnsupportedEncodingException e) {
                    return " - ";
                }
            }
        }
        return " - ";
    }

    private String getResponseBody(final HttpServletResponse response) throws IOException {
        String payload = null;
        ContentCachingResponseWrapper wrapper = WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        if (wrapper != null) {
            wrapper.setCharacterEncoding("UTF-8");
            byte[] buf = wrapper.getContentAsByteArray();
            if (buf.length > 0) {
                payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
                wrapper.copyBodyToResponse();
            }
        }
        return null == payload ? " - " : payload;
    }
}


/*
2022-03-01 01:37:04.049  INFO 16344 --- [nio-8080-exec-6] com.example.api.filter.LoggingFilter     : request header: {content-length=51, postman-token=d4e2bfa4-1...
2022-03-01 01:37:04.050  INFO 16344 --- [nio-8080-exec-6] com.example.api.filter.LoggingFilter     : request body: {
    "param1": "test1",
    "param2": "test2"
}
2022-03-01 01:37:04.051  INFO 16344 --- [nio-8080-exec-6] com.example.api.filter.LoggingFilter     : response body: {"res1":"test1","res2":"test2","res3":"test3"}
*/

Filter 에서 ContentCachingRequestWrapper / ContentCachingResponseWrapper 래퍼로 request 와 response 를 캐시하여, 재사용이 가능하도록 하였다. 밑에 메소드 3개는 각각 헤더, 요청 본문, 응답 본문 가져오기.

이렇게 ContentCaching* 클래스로 간단하게 요청/응답 본문을 로깅할 수 있었다. 심플한건 좋았지만, 내가 원했던 방법은 이렇게 filter 에 전부 때려박는 것은 아니었다. 요청 본문은 preHandle 에서 로깅하고 싶었는데, 제약 조건이 많았다. preHandle 에서 ContentCachingRequestWrapper 로는 json 을 처리하지 못했다. 하지만 form-urlencoded 요청의 경우, application.properties 에서 logging.level.org.springframework.web=debug 설정이 되어 있다면, 인터셉터 preHandle 에서도 요청 본문 로깅이 가능했다. Exception 발생시 응답 본문은 null 이 발생했으나, 이 경우 상태 코드로 응답 예측이 가능하니 큰 문제는 없었다. multipart/form-data 요청은 용량 차지하지 않게 별도로 알아서 잘 처리하시고... (난 그냥 본문 날려버렸음.)

굳이 Spring 에서 처리하긴 했지만, 로깅을 커스텀 하는 것은 쉽지 않았다. 어떤 서비스에 어떤 목적으로 어디에 로깅을 하느냐 또 그 로깅을 어떻게 활용할 것인가가 중요한 것 같다.