Logback MDC로 쉽게 요청 추적하기 (+ Grafana로 추적 더더 쉽게!)

우리는 로그를 통해 사용자의 요청을 추적하고 디버깅합니다.

만약, 수많은 동시 요청이 발생하는 환경에서는 각 요청에 대한 로그를 추적하고 구분하는 것이 어려울 수 있습니다.

Tomcat을 비롯한 대부분의 서블릿 컨테이너는 Thread를 요청마다 생성하는 것이 아니라, Thread Pool을 만들어두고 요청이 들어올 경우 Thread를 재사용하기 때문입니다.

쓰레드풀 재사용, 무엇이 문제냐?

때문에 단순히 Thread 이름으로 로그를 찍게 되면 Thread 이름이 중복된 요청이 발생할 수 있습니다.

만약 에러가 발생했고 상황을 파악하기 위해 로그를 추적할 때, Thread 이름으로 동일한 요청인줄 알고 디버깅하면,,, 헤매는 시간에 더해서 빠른 시간 안에 적절한 대응이 어려워지는 사태로 이어질 수 있습니다.

 

때문에 해결하기 위해 각 요청마다 로그를 출력할 경우 Thread 이름이 아닌 다른 구분값을 찍게 되면 좋을 것 같다는 생각이 듭니다.

이때 우리는 Logback의 MDC를 활용할 수 있습니다. 

---

MDC란?

SLF4J는 자바 애플리케이션을 위한 로깅 프레임워크입니다. 여러 로깅 프레임워크에 대한 추상화 계층을 제공하여, 개발자가 특정 로깅 구현체에 종속되지 않고 유연하게 로깅 기능을 사용할 수 있게 해줍니다.

 

MDC는 이 SLF4J에서 제공하는 기능으로, 스레드별로 고유한 컨텍스트 정보를 저장하고 관리할 수 있게 해줍니다.

이를 통해 로그 메시지에 추가적인 컨텍스트 정보를 포함시킬 수 있어, 각 요청을 쉽게 구분하고 추적할 수 있습니다.

 

MDC의 주요 특징

1. MDC는 ThreadLocal을 기반으로 구현되어 있어, 멀티스레드 환경에서도 안전하게 사용할 수 있습니다. 
2. 문자열 Key - Value 형태로 데이터를 저장합니다.
3. 로그 계층 구조에서 하위 로거들이 상위 로거의 MDC 정보를 상속받아 사용할 수 있습니다.

MDC의 활용하기

모든 요청, 응답, 에러, 메서드 시작 전 등등 로그를 찍기 위해 filter, Interceptor, aop 중 어떤 방식을 통해 구현할지를 선택할 수 있습니다.

저는 그중에서도 MDC를 통한 추척은 filter를 사용하여 구현했는데요. 그 이유는 다음과 같았습니다.

1. Filter는 요청 처리의 가장 앞단에서 동작한다.
2. 요청의 시작부터 응답의 끝까지 전체 생명주기를 커버할 수 있다.

처음 제가 MDC를 사용하려는 목적이 로그를 추적하기 위함이고, 요청의 시작부터, 처리되는 과정, 응답까지를 추적하기 위한 것이었기 때문에 가장 앞단에 위치한 Servlet의 filter를 사용하기로 했습니다.

 

MDC 사용 코드

코드 예시는 다음과 같습니다.

요청을 추적하기 위한 UUID 값을 만들고 MDC를 호출해서 넣어주기만 하면 됩니다.

@Slf4j
@Component
public class MDCFilter implements Filter {
    private final String REQUEST_ID = "correlationId";

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
            throws IOException, ServletException {
        MDC.put(CORRELATION_ID, generateCorrelationId());
        chain.doFilter(request, response);
        MDC.clear(); // // 또는 MDC.remove(REQUEST_ID);
    }

    private String generateCorrelationId() {
        return UUID.randomUUID()
                .toString()
                .substring(0, 8);
    }
}

 

MDC 주의점

주의할 점은 clear 또는 remove가 꼭 필요하다는 것입니다.

사실 현재는 MDC에 데이터를 넣는 곳이 이 필터 밖에 없고 그마저도 매번 requestId를 덮어쓰기 때문에 괜찮을 수 있습니다.

하지만 만약 다른 필터에서 특정 상황에만 다른 Key 값에 Value를 넣는 로직이 있다면, 쓰레드가 재사용될 때 예상치 못한 상황이 발생할 수 있습니다. 따라서 그 상황을 예방하기 위해 반드시 remove 또는 clear를 하는 것을 추천합니다.

 

MDC 적용 후 

쓰레드 명이 아닌, 다른 식별값을 가지고 있는 것을 확인할 수 있습니다.

 

---

⚡️ Grafana로 더 추적 쉽게 하기 

여기서 한번 더 추적을 쉽게 하기 위해 모니터링 대시보드와 연동할 수 있습니다.

로그 모니터링을 위해 프롬테일이라는 에이전트를 사용해서 로그를 보내고 있었는데요!

이때 정형화된 로그의 내용을 파싱하기 위해 다음과 같은 regex를 적었었습니다.

 

이 regex를 통해 요청 추적값을 필드로 등록하게 되면 그라파나에서 다음과 같이 해당 필터 값을 가진 로그로 필터링이 가능합니다.

(fields의 + 돋보기 모양을 클릭하면 filters이 됩니다!)

 

 

필터링 전후!

 

결과적으로 더욱 더 빠르게 로그 추적이 가능합니다 👍