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

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

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

[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 로그를 내맘대로 바꿔보는 방법에 대해서 알아보았습니다.

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

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

개발자로서 운영이슈를 해결하기 위해서는 로그메시지가 디버깅을 위해서 꼭 필요하다는건 누구나 알고계실겁니다.

하지만 로깅을 잘 하기 위해서는 많은 고민이 필요합니다.

로그레벨은 어떻게 할지 로그의 내용은 어떤 정보들로 채워넣을지 등등 말이죠.

로그는 많이 남긴다고 좋은게 아니죠.

어떤 분들은 아무런 의미도 없는 정보를 로깅하기도 합니다.

비용적인 측면이 문제되지 않는다면 대량의 로그를 마음껏 남겨도 되겠지만 현실은 그렇지 않죠.

따라서 중요도에 따라서 적당~~히 최소한의 내용만 로깅하는게 좋습니다.

로그 중에서 가장 중요한 로그는 요청과 응답에 대한 것입니다.

API 요청시 어떤 정보를 전달받았는지에 대한 request log과

그 데이터를 기준으로 비즈니스 로직을 태운 뒤에 어떤 응답을 내주었는지

response log 만 있어도 디버깅은 충분히 가능하죠.

물론 요청과 응답 중간에 로직이 복잡하다면 중간중간 추가적인 로그를 심어주는게 많은 도움이 될 수 있습니다.

그래서 이번 포스팅에서는 요청과 응답을 어떻게 로깅하는지에 대해 공유드리고자 합니다.

1. 프로젝트 생성

기본적인 개발환경은 아래와 같습니다.

• IntelliJ IDEA 2021.3.3 (Ultimate Edition)
• SpringBoot 2.7.3
• Java 18 (OpenJDK)

자, 우선 깡통 프로젝트를 만들겠습니다.

자, 깡통 프로젝트가 완성되었습니다. 

2. 라이브러리 추가

이제 개발편의를 위해 lombok과 로깅을 위한 logback 라이브러리를 추가하고, API 개발을 위해 spring-boot-starter-web 라이브러리를 추가하겠습니다.

implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.projectlombok:lombok:1.18.24'
annotationProcessor 'org.projectlombok:lombok:1.18.24'
implementation 'ch.qos.logback:logback-classic:1.2.11'

3. API 작성

그리고 아래와 같이 테스트용 컨트롤러를 하나 작성해줍니다.

package com.keichee.demo.controller;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.*;

@Slf4j
@RestController
@RequestMapping("/test")
public class TestController {

    @GetMapping("/log")
    public int requestResponseLog(@RequestParam int code) {
        log.info("requestResponseLog method called with code {}", code);
        return code;
    }
}

여기까지하고 앱을 기동한 뒤 API를 호출하여 로그가 잘 남는지 확인해볼게요.

2022-09-15 17:04:50.580  INFO 92637 --- [           main] com.keichee.demo.DemoLoggingApplication  : No active profile set, falling back to 1 default profile: "default"
2022-09-15 17:04:51.034  INFO 92637 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2022-09-15 17:04:51.038  INFO 92637 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-09-15 17:04:51.038  INFO 92637 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.65]
2022-09-15 17:04:51.105  INFO 92637 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-09-15 17:04:51.107  INFO 92637 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 495 ms
2022-09-15 17:04:51.306  INFO 92637 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2022-09-15 17:04:51.312  INFO 92637 --- [           main] com.keichee.demo.DemoLoggingApplication  : Started DemoLoggingApplication in 0.879 seconds (JVM running for 1.294)
2022-09-15 17:05:56.173  INFO 92637 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-09-15 17:05:56.173  INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-09-15 17:05:56.174  INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2022-09-15 17:05:56.186  INFO 92637 --- [nio-8080-exec-1] c.k.demo.controller.TestController       : requestResponseLog method called with code 2

제일 마지막줄에 보면 TestController에서 출력한 로그가 보이네요.

비즈니스 로직의 로그는 잘 출력되고 있으니 이제 기본적인 준비가 끝났습니다.

4. Filter 구현

요청과 응답에 대한 로그출력을 위해서 우리는 Filter를 이용할 겁니다. 

spring-web에서는 아래와 같이 여러 종류의 filter를 제공하고 있습니다.

AbstractRequestLoggingFilter
CharacterEncodingFilter
CommonsRequestLoggingFilter
CompositeFilter
CorsFilter
DelegatingFilterProxy
FormContentFilter
ForwardedHeaderFilter
GenericFilterBean
HiddenHttpMethodFilter
HttpPutFormContentFilter
OncePerRequestFilter
RelativeRedirectFilter
RelativeRedirectResponseWrapper
RequestContextFilter
ServletContextRequestLoggingFilter
ServletRequestPathFilter
ShallowEtagHeaderFilter

여기서 request logging과 관련된 filter는 AbstractRequestLoggingFilter, CommonsRequestLoggingFilter, 그리고 ServletContextRequestLoggingFilter 가 있습니다.

우리는 AbstractRequestLoggingFilter를 상속해서 우리만의 필터를 만들어 볼거에요.

com.keichee.demo 패키지 아래에 filter 패키지를 만들고 이 안에 RequestLoggingFilter 라는 클래스를 아래와 같이 만들어주세요

package com.keichee.demo.filter;

import lombok.extern.slf4j.Slf4j;
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 java.io.IOException;

@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);
    }
}

이제 이 필터를 빈으로 등록해줘야 합니다.

com.keichee.demo 패키지 아래에 config 패키지를 만들고 이 안에 RequestLoggingConfig 클래스를 만들겠습니다.

package com.keichee.demo.config;

import com.keichee.demo.filter.RequestLoggingFilter;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class RequestLoggingConfig {

    public static int MAX_PAYLOAD_LENGTH = 1000;

    @Bean
    public RequestLoggingFilter loggingFilter() {
        RequestLoggingFilter filter = new RequestLoggingFilter();
        filter.setIncludeClientInfo(true);
        filter.setIncludeHeaders(false);
        filter.setIncludePayload(true);
        filter.setIncludeQueryString(true);
        filter.setMaxPayloadLength(MAX_PAYLOAD_LENGTH);
        return filter;
    }
}

헤더정보 로깅이 필요할 경우 setIncludeHeaders(true)로 설정해주시면 됩니다.

payload의 max length는 로깅량과 로그를 저장하는 시스템의 용량 등에 따라 적당히 설정해주시면됩니다. 

이제 마지막 한스텝이 남았습니다.

logback-spring.xml 파일을 resources 디렉토리에 추가해줍니다.

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

<configuration>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

    <springProfile name="local">
        <logger name="com.keichee.demo" level="debug" additivity="false">
            <appender-ref ref="CONSOLE"/>
        </logger>

        <root level="error">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

</configuration>

지금까지 작성한 파일들을 포함하여 최종적으로 패키지 트리를 보면 아래와 같습니다.

이제 active profile 값에 local 을 주고 앱을 재기동한뒤 필터가 정상적으로 적용되었는지 확인해보겠습니다.

2022-09-16 07:28:54.399 DEBUG 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : Running with Spring Boot v2.7.3, Spring v5.3.22
2022-09-16 07:28:54.399  INFO 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : The following 1 profile is active: "local"
2022-09-16 07:28:54.751 DEBUG 31518 --- [           main] c.k.demo.filter.RequestLoggingFilter     : Filter 'loggingFilter' configured for use
2022-09-16 07:28:54.866  INFO 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : Started DemoLoggingApplication in 0.607 seconds (JVM running for 0.819)

출력되는 로그 중에 Filter 'loggingFilter' configured for use 가 출력된걸로 보아 정상적으로 적용이 된 것으로 확인됩니다.

이제 기존에 만들어 두었던 API를 다시 호출해보겠습니다.

2022-09-16 07:29:18.541  INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : Before request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]
2022-09-16 07:29:18.550  INFO 31518 --- [nio-8080-exec-2] c.k.demo.controller.TestController       : requestResponseLog method called with code 2
2022-09-16 07:29:18.560  INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : After request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]

요청에 대한 정보 uri와 query parameter 그리고 client에 X-Forwarded-For 값이 출력된 것을 볼 수 있고, 비즈니스 로직 실행이 끝난 뒤 소요시간이 얼마인지 http status 값이 뭔지 출력되는 것을 확인할 수 있습니다.

지금까지 요청에 대한 uri, query parameter와 API를 요청한 클라이언트의 IP 를 출력하고,

응답을 주기까지의 소요시간과 응답 상태값을 로깅하도록 설정을 해보았습니다. 여기까지 잘 따라 오셨나요? 😋

이제 request body 를 입력받아 payload가 잘 출력되는지 보겠습니다.

TestController 에 request body를 받는 API를 하나 추가하겠습니다.

@PostMapping("/request-body-log")
public long requestBodyLog(@RequestBody Employee employee) {
    return employee.getId();
}

Employee 정보를 받아서 id를 그대로 리턴해주는 간단한 API입니다. (어차피 request body 로깅을 위한거니 심플하게 

그리고 domain 패키지 하위에 Employee 클래스를 아래와 같이 생성해주겠습니다.

@Getter
@Setter
@FieldDefaults(level = AccessLevel.PRIVATE)
public class Employee {
    long id;
    String name;
    int age;
}

이제  앱을 기동해서 postman으로 테스트를 해보겠습니다.

로그는 아래와 같이 출력되었습니다.

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
}]

그런데 로그를 보니 uri 정보와 client 정보가 중복되서 출력이 되고 있고, request body로 넘겨준 데이터가 비즈니스 로직이 모두 실행되고 난 뒤에 출력되는 After request ... 부분에 출력이 되고 있습니다. 뭔가 출력되는 내용이 마음에 들지 않네요. 

다음 포스팅에서는 로그메시지를 바꿔보도록 하겠습니다.

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

도움이 되셨다면 좋아요 꾹 눌러주고 가세요~

[ 다음 포스팅 바로 읽기 ]