지난 포스팅에서 요청과 응답에 대한 로그를 남기는 법에 대해서 알아보았었는데요

이어서 이번에는 출력되는 로그메시지의 내용을 바꿔보려고 합니다.

혹시라도 검색으로 이 포스팅을 먼저 보게되시는 분은 아래 포스팅을 먼저 읽어보시길 추천드립니다.

[5분코딩] Filter를 이용한 요청,응답 로깅 (How to log request, response info inlcuding payload using filter) - (1/2)

로그 메시지 내맘대로 꾸미기

우선 지난 시간에 마지막으로 확인한 로그 출력 내용을 다시 확인해보면 아래와 같습니다.

2022-09-16 07:32:49.190  INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter     : Before request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1]
2022-09-16 07:32:49.226  INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter     : After request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1, payload={
    "id":1000,
    "name":"케이치",
    "age":20
}]

그럼 저 메시지를 어떻게 바꿀 수 있을지 한번 알아볼게요.

요청/응답 로깅을 위해서 우리는 AbstractRequestLoggingFilter 를 상속하여 필터를 하나 만들었었습니다.

로그 메시지를 바꾸려면 저 클래스에서 어떤 메서드들을 제공하고 있는지 들여다봐야 합니다. 

AbstractRequestLoggingFilter를 까보면 아래 메서드를 오버라이드해서 재정의하고 있는 것을 볼 수 있습니다.

protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)

doFilterInternal 메서드에서 하는 일은 요청에 대한 비즈니스 로직이 실행되기 전후로 로그를 남기는 것입니다.

코드를 잠시 살펴볼게요

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

   boolean isFirstRequest = !isAsyncDispatch(request);
   HttpServletRequest requestToUse = request;

   if (isIncludePayload() && isFirstRequest && !(request instanceof ContentCachingRequestWrapper)) {
      requestToUse = new ContentCachingRequestWrapper(request, getMaxPayloadLength());
   }

   boolean shouldLog = shouldLog(requestToUse);
   if (shouldLog && isFirstRequest) {
      beforeRequest(requestToUse, getBeforeMessage(requestToUse));
   }
   try {
      filterChain.doFilter(requestToUse, response);
   }
   finally {
      if (shouldLog && !isAsyncStarted(requestToUse)) {
         afterRequest(requestToUse, getAfterMessage(requestToUse));
      }
   }
}

beforeRequest(requestToUse, getBeforeMessage(requestToUse)) 에서 Before request ... 로그를 남기고 있고

afterRequest(requestToUse, getAfterMessage(requestToUse)) 에서 After request ... 로그를 남기고 있습니다.

따라서 우리가 원하는대로 메시지의 내용을 바꾸려면 저 두 군데를 수정해주면 됩니다.

우선 로그 메시지에 대한 수정 요구사항이 아래와 같다고 가정해보겠습니다.

1. 호출받은 API 정보와 클라이언트IP 정보를 중복 출력 하지 않는다
2. 호출받은 API uri 와 클라이언트IP, payload 정보는  before request 에서 남긴다.  🌟
3. after request 에는 응답소요시간과 http status 코드값을 남긴다.
4. 최종적으로 출력되는 모습은 다음과 같다.

2022-09-16 08:28:08.053  INFO 41196 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : REQ: POST uri=/test/request-body-log;client=0:0:0:0:0:0:0:1;payload={
    "id":1000,
    "name":"케이치",
    "age":20
}
2022-09-16 08:28:08.076  INFO 41196 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : RES: 22ms, 400

자, 이제 위 요구사항에 맞게 우리의 필터클래스를 수정해보겠습니다. 

RequestLoggingFilter 클래스에 아래 코드를 추가해주세요.

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

    boolean isFirstRequest = !isAsyncDispatch(request);
    HttpServletRequest requestToUse = request;

    if (isIncludePayload() && isFirstRequest && !(request instanceof ContentCachingRequestWrapper)) {
        requestToUse = new ContentCachingRequestWrapper(request);
    }

    long start = System.currentTimeMillis();

    if (isFirstRequest) {
        beforeRequest(requestToUse, getBeforeMessage(requestToUse));
    }

    try {
        filterChain.doFilter(requestToUse, response);
    } finally {
        if (!isAsyncStarted(requestToUse)) {
            afterRequest(requestToUse, getAfterMessage(System.currentTimeMillis() - start, response.getStatus()));
        }
    }
}

private String getBeforeMessage(HttpServletRequest request) {
    return createMessage(request, "REQ: ", "");
}

private String getAfterMessage(long elapsed, int status) {
    return "RES: " + elapsed + "ms, " + status;
}

AbstractRequestLoggingFilter 에 구현되어있는 doFilterInternal 메서드 내용을 그대로 가지고와서 beforeRequest와 afterRequest 메서드의 두 번째 파라미터로 전달하는 message 를 조립하는 메서드를 직접 구현합니다. getBeforeMessage의 createMessage는 super클래스, 즉, AbstractRequestLoggingFilter 에서 제공하는 것을 그대로 사용합니다. createMessage 에서는 prefix와 suffix 그리고 request 정보를 가지고 메시지를 알아서 만들어 줍니다. payload도 역시 여기 포함되어있죠.

자, 그럼 앱을 재기동하고 로깅이 어떻게 되는지 보겠습니다.

2022-09-16 08:39:20.270  INFO 43287 --- [nio-8080-exec-1] c.k.demo.filter.RequestLoggingFilter     : REQ: POST /test/request-body-log, client=0:0:0:0:0:0:0:1
2022-09-16 08:39:20.306  INFO 43287 --- [nio-8080-exec-1] c.k.demo.filter.RequestLoggingFilter     : RES: 35ms, 200

요구사항 대부분이 반영된 것을 확인할 수 있습니다. 어라? 근데 payload 가 request 로그에서 빠져있습니다.

분명 after message 로그가 출력될 때는 잘 출력이 됐었는데 말이죠. 똑같은 createMessage 메서드를 이용했는데 before request 에서는 payload가 출력이 안됩니다 ㅜㅜ

확인해보니 AbstractRequestLoggingFilter.getMessagePayload 에서 아래 wrapper 가 null 로 반환이 되고있었습니다.

ContentCachingRequestWrapper wrapper =
      WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);

res로그에서는 잘 나오던게 req로그에서 출력하려니 null이 반환이 됩니다.

이걸 해결하려면 추가적인 작업이 필요한데 우선 아래 두 개의 클래스를 추가해줍니다.

package com.keichee.demo.filter;

import org.springframework.stereotype.Component;
import org.springframework.web.filter.GenericFilterBean;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import java.io.IOException;

@Component
public class RequestBodyCacheFilter extends GenericFilterBean {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain chain)
            throws IOException, ServletException {
        chain.doFilter(new RequestBodyCacheWrapper((HttpServletRequest) servletRequest), servletResponse);
    }
}

package com.keichee.demo.filter;

import lombok.extern.slf4j.Slf4j;

import javax.servlet.ReadListener;
import javax.servlet.ServletInputStream;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletRequestWrapper;
import java.io.*;
import java.nio.charset.StandardCharsets;

@Slf4j
public class RequestBodyCacheWrapper extends HttpServletRequestWrapper {

    private final ByteArrayInputStream byteArrayInputStream;

    public RequestBodyCacheWrapper(HttpServletRequest request) throws IOException {
        super(request);
        InputStream is = super.getInputStream();
        byteArrayInputStream = new ByteArrayInputStream(is.readAllBytes());
    }

    @Override
    public ServletInputStream getInputStream() {
        byteArrayInputStream.reset();
        return new MyServletInputStream(byteArrayInputStream);
    }

    @Override
    public BufferedReader getReader() {
        byteArrayInputStream.reset();
        return new BufferedReader(new InputStreamReader(byteArrayInputStream, StandardCharsets.UTF_8));
    }


    private static class MyServletInputStream extends ServletInputStream {

        private final InputStream is;

        public MyServletInputStream(InputStream bis) {
            is = bis;
        }

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

        @Override
        public int read(byte[] b) throws IOException {
            return is.read(b);
        }

        @Override
        public boolean isFinished() {
            return false;
        }

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

        @Override
        public void setReadListener(ReadListener readListener) {
        }
    }
}

이제 다시 RequestLoggingFilter 클래스로 돌아와서 AbstractRequestLoggingFilter.createMessage 메서드를 그대로 복사해서 가지고 옵니다. 그리고 getMessagePayload 부분을 아래와 같이 수정해주세요. 다른 부분은 그대로 놔둡니다.

String payload = null;
try {
    payload = new String(request.getInputStream().readAllBytes(), StandardCharsets.UTF_8);
} catch (IOException e) {
    log.error("failed to read payload", e);
}

수정이 완료된 createMessage 메서드는 아래와 같습니다.

@Override
protected String createMessage(HttpServletRequest request, String prefix, String suffix) {
    StringBuilder msg = new StringBuilder();
    msg.append(prefix);
    msg.append(request.getMethod()).append(' ');
    msg.append(request.getRequestURI());

    if (isIncludeQueryString()) {
        String queryString = request.getQueryString();
        if (queryString != null) {
            msg.append('?').append(queryString);
        }
    }

    if (isIncludeClientInfo()) {
        String client = request.getRemoteAddr();
        if (StringUtils.hasLength(client)) {
            msg.append(", client=").append(client);
        }
        HttpSession session = request.getSession(false);
        if (session != null) {
            msg.append(", session=").append(session.getId());
        }
        String user = request.getRemoteUser();
        if (user != null) {
            msg.append(", user=").append(user);
        }
    }

    if (isIncludeHeaders()) {
        HttpHeaders headers = new ServletServerHttpRequest(request).getHeaders();
        if (getHeaderPredicate() != null) {
            Enumeration<String> names = request.getHeaderNames();
            while (names.hasMoreElements()) {
                String header = names.nextElement();
                if (!getHeaderPredicate().test(header)) {
                    headers.set(header, "masked");
                }
            }
        }
        msg.append(", headers=").append(headers);
    }

    if (isIncludePayload()) {
        String payload = null;
        try {
            payload = new String(request.getInputStream().readAllBytes(), StandardCharsets.UTF_8);
        } catch (IOException e) {
            log.error("failed to read payload", e);
        }
        if (payload != null) {
            msg.append(", payload=").append(payload);
        }
    }

    msg.append(suffix);
    return msg.toString();
}

마지막으로 doFilterInternal 메서드 로직 중 filterChain.doFilter에서 사용하는 request 객체를 ContentCachingRequestWrapper 가 아닌 메서드 파라미터로 전달받은 request를 그대로 사용하도록 수정합니다. (reuqestToUse -> request)

최종적으로 RequestLoggingFilter 클래스의 소스코드는 다음과 같습니다.

package com.keichee.demo.filter;

import lombok.extern.slf4j.Slf4j;
import org.springframework.http.HttpHeaders;
import org.springframework.http.server.ServletServerHttpRequest;
import org.springframework.util.StringUtils;
import org.springframework.web.filter.AbstractRequestLoggingFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import javax.servlet.http.HttpSession;
import java.io.IOException;
import java.nio.charset.StandardCharsets;
import java.util.Enumeration;

@Slf4j
public class RequestLoggingFilter extends AbstractRequestLoggingFilter {

    @Override
    protected void beforeRequest(HttpServletRequest request, String message) {
        logger.info(message);
    }

    @Override
    protected void afterRequest(HttpServletRequest request, String message) {
        logger.info(message);
    }

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

        boolean isFirstRequest = !isAsyncDispatch(request);
        HttpServletRequest requestToUse = request;

        if (isIncludePayload() && isFirstRequest && !(request instanceof ContentCachingRequestWrapper)) {
            requestToUse = new ContentCachingRequestWrapper(request);
        }

        long start = System.currentTimeMillis();

        if (isFirstRequest) {
            beforeRequest(requestToUse, getBeforeMessage(requestToUse));
        }

        try {
            filterChain.doFilter(request, response);
        } finally {
            if (!isAsyncStarted(requestToUse)) {
                afterRequest(requestToUse, getAfterMessage(System.currentTimeMillis() - start, response.getStatus()));
            }
        }
    }

    private String getBeforeMessage(HttpServletRequest request) {
        return createMessage(request, "REQ: ", "");
    }

    private String getAfterMessage(long elapsed, int status) {
        return "RES: " + elapsed + "ms, " + status;
    }

    @Override
    protected String createMessage(HttpServletRequest request, String prefix, String suffix) {
        StringBuilder msg = new StringBuilder();
        msg.append(prefix);
        msg.append(request.getMethod()).append(' ');
        msg.append(request.getRequestURI());

        if (isIncludeQueryString()) {
            String queryString = request.getQueryString();
            if (queryString != null) {
                msg.append('?').append(queryString);
            }
        }

        if (isIncludeClientInfo()) {
            String client = request.getRemoteAddr();
            if (StringUtils.hasLength(client)) {
                msg.append(", client=").append(client);
            }
            HttpSession session = request.getSession(false);
            if (session != null) {
                msg.append(", session=").append(session.getId());
            }
            String user = request.getRemoteUser();
            if (user != null) {
                msg.append(", user=").append(user);
            }
        }

        if (isIncludeHeaders()) {
            HttpHeaders headers = new ServletServerHttpRequest(request).getHeaders();
            if (getHeaderPredicate() != null) {
                Enumeration<String> names = request.getHeaderNames();
                while (names.hasMoreElements()) {
                    String header = names.nextElement();
                    if (!getHeaderPredicate().test(header)) {
                        headers.set(header, "masked");
                    }
                }
            }
            msg.append(", headers=").append(headers);
        }

        if (isIncludePayload()) {
            String payload = null;
            try {
                payload = new String(request.getInputStream().readAllBytes(), StandardCharsets.UTF_8);
            } catch (IOException e) {
                log.error("failed to read payload", e);
            }
            if (payload != null) {
                msg.append(", payload=").append(payload);
            }
        }

        msg.append(suffix);
        return msg.toString();
    }

}

자, 이제 앱을 재기동하고 다시 API를 호출해보겠습니다.

2022-09-16 10:04:36.918 DEBUG 57590 --- [           main] com.keichee.demo.DemoLoggingApplication  : Running with Spring Boot v2.7.3, Spring v5.3.22
2022-09-16 10:04:36.918  INFO 57590 --- [           main] com.keichee.demo.DemoLoggingApplication  : The following 1 profile is active: "local"
2022-09-16 10:04:37.301 DEBUG 57590 --- [           main] c.k.demo.filter.RequestBodyCacheFilter   : Filter 'requestBodyCacheFilter' configured for use
2022-09-16 10:04:37.301 DEBUG 57590 --- [           main] c.k.demo.filter.RequestLoggingFilter     : Filter 'loggingFilter' configured for use
2022-09-16 10:04:37.416  INFO 57590 --- [           main] com.keichee.demo.DemoLoggingApplication  : Started DemoLoggingApplication in 0.642 seconds (JVM running for 0.873)
2022-09-16 10:04:39.588  INFO 57590 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : REQ: POST /test/request-body-log, client=0:0:0:0:0:0:0:1, payload={
    "id":1000,
    "name":"케이치",
    "age":20
}
2022-09-16 10:04:39.627  INFO 57590 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : RES: 40ms, 200

request payload가 정상적으로 출력되는 것을 확인할 수 있습니다. 응답 status도 200이 나온것을 확인했습니다.

자, 잘 따라 오셨나요? 

이 부분은 tricky한 부분이라 비즈니스 로직이 실행되기 전에 request body를 출력하는 부분에서 애를 먹는 분들이 많습니다. stackoverflow에서 해결책을 찾기도 힘들더군요. 의도한건지는 모르겠으나 springboot에 내장된 tomcat에 request body를 한번만 읽어서 쓸 수 있도록 제한(?)되어있기 때문에 잘못 설정하면 로그에는 payload가 잘 출력되지만 비즈니스로직 실행시 request body를 못 읽어와서 400 bad request가 발생하기도 합니다.

이상으로 request, response 로그를 내맘대로 바꿔보는 방법에 대해서 알아보았습니다.

읽어주셔서 감사합니다~ 🙇

좋아요 꾹 눌러주고 가세요~