MDC(Mapped Diagnostics Context)를 사용하여 로그 추적하기

로깅이란

로깅이란, 시스템이 동작할 때 시스템의 상태 및 동작 정보를 기록하는 것을 의미한다. 로깅을 통해 개발자는 개발 과정 또는 개발 후에 발생할 수 있는 예상치 못한 애플리케이션의 문제를 진단할 수 있고, 다양한 정보를 수집할 수 있다. 사용자 로그의 경우 분석 데이터로 활용할 수도 있다.

하지만 적절한 수준의 로그 기록 기준을 잡지 못하면 방대한 양의 로그 파일이 생성되는 문제를 겪거나, 의미 있는 로그를 쌓지 못하는 경우가 발생할 수 있다. 결국 효율적으로 로깅하는 방법을 이해하는 것이 중요하다.

로깅 라이브러리

로깅 관련 프레임워크는 대표적으로 log4j, logback, log4j2가 있고, 이들으르 통합해서 인터페이스로 제공하는 slf4j 라이브러리가 있다. 현재 log4j는 deprecated되었으며, logback이 가장 널리 사용되고 있다.

logback은 log4j 이후에 출시되어, 보편적으로 사용되고 있는 자바 진영의 로깅 프레임워크이다. slf4j는 인터페이스이고, logback은 slf4j의 구현체로 동작한다. 따라서 spring-boot-starter-web에는 spring-boot-starter-logging이 포함되어 있어서 별다른 의존성 추가 없이 사용 가능하다. 우리가 일반적으로 LoggerFactory 를 직접 선언하거나 @Slf4j 어노테이션을 통해 로깅을 구현할텐데, 이에 대한 구현체는 logback이다.

로그 레벨

logback은 5단계의 로그 레벨을 갖는다. 심각도 수준은 Error > Warn > Info > Debug > Trace이다.

Error: 예상하지 못한 심각한 문제가 발생하는 경우, 즉시 조취를 취해야 할 수준의 레벨
Warn: 예상 가능한 문제로 인한 예외 처리, 당장 서비스 운영에는 영향이 없지만 주의해야 할 부분
Info: 운영에 참고할만한 사항, 중요한 비즈니스 프로세스가 완료됨
Dedug: 개발 단계에서 디버깅 용도
Trace: Debug 레벨보다 더 세부적인 실행 흐름을 추적하는 경우

Debug과 Trace 레벨은 많은 양의 로그가 쌓이므로 자칫 운영 단계에서 해당 레벨의 로깅을 할 경우 용량이 쌓일 수 있다. 불필요한 로그를 모두 남기게 되면 데이터 저장 공간이 낭비되고, 너무 많은 로그로 인해 추적이 어려울 수 있다. 따라서 필요한 정보만 로깅하고 Debug, Trace 레벨의 로깅은 개발 단계에서만 사용하고 배포 단계에서는 사용하지 말자.

로그가 섞이는 문제

일반적으로 웹 서버는 멀티스레드 환경에서 동작하며 하나의 클라이언트 요청에 대해 하나의 스레드가 할당되어 처리된다. 이 상황에서 로그를 남기게 되면, 여러 요청에 대한 로그가 섞이게 되어, 문제가 발생했을 때 추적하기 어렵다. 이런 문제를 해결하기 위해 로그와 함께 하나의 요청에 대한 로그들을 하나로 묶을 수 있는 맥락(Context)을 남길 필요가 있다.

나의 경우, 필터에서 UUID를 생성하여 Trace Id를 남기도록 했다. 이를 통해 로그가 섞이더라도 Trace Id를 통해 하나의 요청에 대한 로그들을 추적할 수 있다. (Trace Id는 MSA 등 분산 환경에서 요청을 추적하기 위해 사용되는 Id를 의미한다. 현재 프로젝트는 단일 서버이지만 Trace Id라는 용어를 사용했다.)

Trace Id를 로그로 남기는 가장 간단한 방법은 모든 메서드를 호출할 때마다 파라미터로 Trace Id를 넘겨주는 방법이 있다. 그러나 이 방법은 번거로우며 비효율적이다. MDC를 사용하면 이런 문제를 해결할 수 있다.

MDC(Mapped Diagnostics Context)

slf4j는 MDC(Mapped Diagnostics Context)라는 기능을 제공한다. MDC는 내부적으로 스레드 로컬을 사용하여 구현되어 있으며, 이름에서 알 수 있듯이 Map 형태로 Context를 관리한다.

MDC.put("key", "value") // 컨텍스트 추가
MDC.get("key") // 컨텍스트 조회
MDC.clear() // 컨텍스트 초기화

따라서 다음과 같이 Filter에서 Trace Id를 생성한 후 MDC에 저장해주면 된다. 참고로 요청마다 로그를 남기기 위해 필터에서도 로그를 남겼다.

@Slf4j
public class LogFilter implements Filter {
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        String traceId = UUID.randomUUID().toString();
        String requestURI = httpRequest.getRequestURI();
        String method = httpRequest.getMethod();
        
        try {
            log.info("REQUEST [{}][{} {}]", traceId, method, requestURI);
            MDC.put("traceId", traceId); // MDC에 저장
            chain.doFilter(request, response);
        } catch (Exception e) {
            throw e;
        } finally {
            log.info("RESPONSE [{}][{} {}]", traceId, method, requestURI);
            MDC.clear(); // MDC 정리
        }
    }
}

그리고 다음과 같이 로깅을 남길 때 `MDC.get()`을 통해 Trace Id를 함께 남기면 된다.

@Slf4j
@RestController
public class TestController {

    @GetMapping("/test")
    public void test() {
        log.info("traceId = {}", MDC.get("traceId"));
        ...
    }
}

그런데 매번 `MDC.get()`을 하기 번거로우므로 글로벌하게 설정할 수 있다. 다음과 같이 logback.xml 파일을 작성하자.

<configuration>
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />

    <!-- 로그 형식 설정 -->
    <property name="CONSOLE_LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss}][%thread] %clr(%5level) %cyan(%logger) [%X{traceId:-NoTraceId}] - %msg%n" />
    <property name="FILE_LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss}][%thread] %5level %logger [%X{traceId:-NoTraceId}] - %msg%n" />

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>./log/application.log</file>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

`%X{MDC_KEY}`를 사용하여 MDC에 저장된 값을 꺼내올 수 있다. 즉, `%X{traceId}`로 설정하면 traceId라는 이름의 키 값을 꺼내온다. 그런데 traceId가 없으면 공백이 출력된다. 따라서 `%X{MDC_KEY:-TEXT}` 형태로 설정하면 키를 MDC에서 찾을 수 없을 때 대체할 텍스트를 설정할 수 있다. 나의 경우 `%X{traceId:-NoTraceId}`를 통해 traceID가 MDC에 없으면 NoTraceId를 출력하도록 했다.

앞서 MDC는 내부적으로 스레드 로컬을 사용한다고 했다. 그렇다면 직접 스레드 로컬을 사용하면 되지 않을까? 왜 MDC를 사용해야 할까? 물론 스레드 로컬을 직접 사용하여 로깅할 수도 있지만, 매번 스레드 로컬에서 값을 꺼내와야 하는 번거로움이 있다. 그러나 MDC를 사용하면 로그 포맷에 맞춰 로그 메시지에 Trace Id가 자동으로 추가되어 편리하고 코드를 줄여준다.

Reference

저작자표시