Spring Logging (1) : HTTP Request/Response 로그 남기기

서비스를 운영하면서 서버가 받는 HTTP 요청과 서버가 제공하는 응답을 로그로 남긴다면, 추후 무슨 일이 생겼을 때 추적이 용이하다. 이번 포스팅은 Spring Boot을 사용하여 로그 남기기 시리즈 중 첫번째 포스팅이다 🥳

본 포스팅에서는 Spring Boot을 사용하여 HTTP 요청과 응답에 대한 로그를 남기고, 이 로그를 추적하기 용이하게 HTTP 요청당 Trace Id를 부여하겠다.
다음 포스팅에서 실행중인 프로파일(dev, prod 등)에 따라 콘솔에 로그를 출력할지, 혹은 AWS CloudWatch에 로그를 전송할지 설정하는 예제까지 다룬다.

작업 결과 미리보기

콘솔로그

맨 아래 두 줄의 로그를 잘 봐보자. HTTP Request와 Response에 대한 로그를 출력하고 있다.
그리고 하나의 HTTP 요청에 대해 동일한 traceId를 부여하고 있기 때문에, 두 줄의 로그가 하나의 요청에 의해 출력되었음을 알 수 있다.

2021-10-10 21:05:44.917 [http-nio-8080-exec-1] [traceId=bf5a5c08-02df-4c01-b7b2-3c8053547f7b] INFO  m.s.s.global.filters.LoggingFilter.logRequest - Request : GET uri=[/samplename=newiia] content-type=[null]
2021-10-10 21:05:44.949 [http-nio-8080-exec-1] [traceId=bf5a5c08-02df-4c01-b7b2-3c8053547f7b] INFO  m.s.s.global.filters.LoggingFilter.logPayload - Response Payload: hello! newiia

---

1. Logback 설정하기

logback은 Spring Boot 기본 로그 라이브러리이기 때문에 별도의 의존성은 추가하지 않아도 된다.
application.yml이 위치한 곳에 logback-spring.xml 을 추가하자.
이 xml 설정파일에서 콘솔에 출력할 로그패턴을 정하고, 대상 프로파일을 설정할 수 있다. 여기서는 dev, prod 프로파일이 아닐 때 커스텀한 콘솔로그 패턴을 적용하도록 설정하였다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>
                %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [traceId=%X{traceId}] %-5level %logger{36}.%M - %msg%n
            </pattern>
        </encoder>
    </appender>

    <springProfile name="!(dev | prod)">
        <root level="info">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

</configuration>

[스프링부트 (5)] Spring Boot 로그 설정(1) - Logback 글을 추천한다. Logback에 대한 간단한 설명과 패턴을 커스텀하는 방법에 대해 자세히 안내하고 있다.

2. Trace Id 부여하기

Trace Id는 Logback에서 제공하는 MDN map을 통해 값을 넣고, Loback에서 로그를 출력할 때 해당 값을 읽어들이도록 한다. 위 xml 설정에서 보면 %X{traceId} 이라는 키워드가 보일텐데, 이 키값과 동일한 이름으로 trace id 값을 생성해줄 것이다.

MDC.put("traceId", UUID.randomUUID().toString());
// TODO 로그 출력
MDC.clear();

3. Filter에서 HTTP Request, Response 출력하기

얼핏 생각하면 Aspect를 사용해서 Controller 전/후에 로그를 출력하면 되지 않을까 생각할 수 있다. 물론 그렇게 설정한다면 정말 최고로 간단하다. 하지만 HTTP는 Spring 외부 영역에서 시작하는, 웹서버 레이어에서 일어나는 작업이다. 만약 Spring 내 Aspect를 실행하기 전에 오류가 발생한다면 HTTP 요청 로그를 남기지 못하게 된다. 그러니까 Filter 에서 HTTP 로그를 남겨보자.

(Filter, Interceptor, AOP 별 사용처에 대해서 간단하게 정리한 포스팅이 있다. (끼워팔기☺️)

요청된 HTTP 정보에 접근하는법 알아보기

Filter에서 HTTP 요청/응답에 접근하는 건 조금 까다롭다. 이 부분에서 많이 헤맸는데, 간단하게 스쳐지나갔던 Filter들을 소개하고, 마지막에 어떤 필터를 사용했는지 코드로 안내하겠다.
먼저 요청된 HTTP에 접근하기 위해 사용했던 것들을 안내하고, 직접 구현 코드를 3-1, 3-2, 3-3에서 안내한다.

TeeFilter
Logback에서 지원하는 TeeFilter는 HTTP Request와 Response를 로깅해준다. 하지만 공식 문서에서 해당 Filter를 실 운영환경에서의 사용을 권장하고 있지 않기 때문에 적용하지는 않았다. 관련 링크를 남긴다.

As mentioned previously, while extremely useful during problem hunting, TeeFilter can introduce new problems. Consequently, we do not recommend having TeeFilter active in production systems.

공식문서

HandlerInterceptorAdapter
참고로 Spring 5.3 이후부터는 Deprecated 되었으므로 직접 HandlerInterceptor 또는 AsyncHandlerInterceptor를 구현해야한다.
하지만 HandlerInterceptorAdapter는 한번 읽어들인 HTTP Request가 소비되어 사라진다는 점에서 로깅을 남기는 목적으로는 적합하지 않다. 이렇게 되면 Controller에서 Request를 받지 못해 오류가 난다.
자세한 내용은 Spring – Log Incoming Requests 내용을 참고해보자. 이 문제를 극복하기 위해 ContentCachingRequestWrapper 에 대해 알아보겠다.

ContentCachingRequestWrapper
ContentCachingRequestWrapper를 상속받아 Logging Filter를 만든다면 HTTP Request를 여러 번 읽어들일 수 있다. 드디어 극복!! 구현 방법에 대해서는 Reading HttpServletRequest Multiple Times in Spring에서 자세히 설명하고 있다. 하지만 Request PayLoad를 읽지 못하고, content-type이 'x-www-form-urlencoded'만 지원하기 때문에 결국 다른 방법을 선택했다. (혹시 이 내용이 틀리다면 댓글로 제보 부탁드립니다.)

HttpServletRequestWrapper
최종 방법이다. HttpServletRequestWrapper를 상속받아서 HTTP Request의 요청과 Payload를 출력한다. 그래! 이것으로 결정했어! (비장)

3-1. HTTP Request/Response Loggin Filter

OncePerRequestFilter를 상속해 로깅하는 필터를 구현했다.

@Component
public class LoggingFilter extends OncePerRequestFilter {
    protected static final Logger log = LoggerFactory.getLogger(LoggingFilter.class);

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        MDC.put("traceId", UUID.randomUUID().toString());
        if (isAsyncDispatch(request)) {
            filterChain.doFilter(request, response);
        } else {
            doFilterWrapped(new RequestWrapper(request), new ResponseWrapper(response), filterChain);
        }
        MDC.clear();
    }

    protected void doFilterWrapped(RequestWrapper request, ContentCachingResponseWrapper response, FilterChain filterChain) throws ServletException, IOException {
        try {
            logRequest(request);
            filterChain.doFilter(request, response);
        } 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));
    }
}

3-2. 요청된 HTTP 접근하기

public class RequestWrapper extends HttpServletRequestWrapper {

    private byte[] cachedInputStream;

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

    @Override
    public ServletInputStream getInputStream() {
        return new ServletInputStream() {
            private InputStream cachedBodyInputStream = new ByteArrayInputStream(cachedInputStream);

            @Override
            public boolean isFinished() {
                try {
                    return cachedBodyInputStream.available() == 0;
                } catch (IOException e) {
                    e.printStackTrace();
                }
                return false;
            }

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

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

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

3-3. HTTP 응답 캐싱하기

public class ResponseWrapper extends ContentCachingResponseWrapper {
    public ResponseWrapper(HttpServletResponse response) {
        super(response);
    }
}

---

본 포스팅 예제는 Github에 올려두었다.

https://github.com/HyunAh-iia/spring-logging

GitHub - HyunAh-iia/spring-logging: Spring Boot Logging HTTP with Trace Id Using Logback and AWS CloudWatch