Logback MDC(Feat. LogFilter,Filter)

스프링 MVC 2편 [서블릿 필터] 강의에서 인터페이스 Filter를 아래와 같이 구현하여 Http 요청과 응답까지의 Log 기록을

남겼다. 

@Slf4j
public class LogFilter implements Filter {


    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

        log.info("log Filter init()");

    }

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

        log.info("log Filter doFilter()");

        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String requestURI = httpRequest.getRequestURI();

        String uuid = UUID.randomUUID().toString();

        try{

            log.info("REQUEST [{} , {}]",uuid,requestURI);
            chain.doFilter(request,response); // 다음에 필터가 없으면, 서블릿 객체(Dispatcher Servlet) 호출하여 요청을 처리


        }catch(Exception e){

            throw e;

        }
        finally{

            log.info("RESPONSE [{} , {}]",uuid,requestURI); // 이 시점에 요청에 대한 처리(chain.doFilter(request,response))
                                                          // 가 끝난 시점!
        }

    }

    @Override
    public void destroy() {
        log.info("log Filter destroy()");
    }
}

(만약 컨트롤러->서비스->레포지토리의 실행 흐름에 대해서도 남기고 싶으면 각 계층에 log.info()를 하면 그만이다)

아래의 그림은 한 개의 Http 요청이 들어오고 처리 완료되어 Http 응답까지의 흐름을 요청한 것이다. 

위 로그에는 매우 불편한 점이 있다. 

한 개의 Http 요청임에도 불구하고, 쓰레드가 2개 사용됐다는 점이다. 

이렇게 되면 특정 Http 요청에 대한 Tracking이 쉽지가 않아 진다. 왜냐하면 쓰레드가 2개이므로 쓰레드 이름도 2개이기 때

문이다.

만약 사용하는 쓰레드가 1개였다면 서버에서 생성된 로그 파일에서 "grep "쓰레드 명" path/log_file_name.log"과 같은 명령

어로 Http 요청에 대한 흐름을 파악하여 디버깅이 가능하다. 

그러나 Tomcat은 미리 쓰레드 풀을 통해 쓰레드 개수를 한정시켜 놓는데, 그때 이미 쓰레드 이름 또한 정해져 있다. 

고로, 만약 Http 요청에 의해 "쓰레드 1"이 할당이 되고 처리 완료 후 쓰레드가 반환되고,  다른 1개의 Http 요청이 들어와 다시 "쓰

레드 1"을 할당해 버리게 되면 쓰레드 명으로는 Log 추적이 어려워 진다(왜냐하면 "쓰레드 1" 이 2개의 Http 요청 중 어떤

요청에 할당된 쓰레드였는지 알 길이 없기 때문이다.)  

그러나 아래의 코드와 같이 쓰레드 명이 아니라 UUID를 사용하면 이 문제가 해결된다. 

코드를 다시 보자!

@Slf4j
public class LogFilter implements Filter {


    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

        log.info("log Filter init()");

    }

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

        log.info("log Filter doFilter()");

        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String requestURI = httpRequest.getRequestURI();

        String uuid = UUID.randomUUID().toString(); // UUID 생성

        try{

            log.info("REQUEST [{} , {}]",uuid,requestURI); // Http 요청을 UUID로 매핑
            chain.doFilter(request,response);

        }catch(Exception e){

            throw e;

        }
        finally{

            log.info("RESPONSE [{} , {}]",uuid,requestURI); // Http 요청을 UUID로 매핑
        }

    }

    @Override
    public void destroy() {
        log.info("log Filter destroy()");
    }
}

 

UUID는 절대 중복된 값을 출력하지 않는다(중복될 확률 : 로또 300번 연속 당첨된 확률)

고로, 로그 파일에서 "grep "쓰레드 명" path/log_file_name.log"과 같은 명령어로 Http 요청에 대한 흐름을 파악하여 디버깅

이 가능해진다. 

 

이와 같이 UUID를 사용하는 것도 하나의 방법이지만 가독성에 약간의 문제가 있다. 

실무에서는 이러한 문제로 인해 Log 관련하여서는 @Slf4j가 제공하는 기능인 Logback MDC 기능을 사용하여 로그의 가

독성을 높인다. 

아래가 MDC를 사용하여 남긴 로그 기록이다. 

 

 

출처 : https://dev-jwblog.tistory.com/126, https://0soo.tistory.com/246