Logback MDC(Mapped Diagnostic Context) 활용하여 Observability 개선하기

 

고민의 시작점

다수의 사람들이 서비스를 이용하는 우아한테크코스의 데모데이 직전,

모니터링이 수월하게 작동할 지 확인하는 도중 다른 크루원과 기존 로깅 방식에 대해 이야기를 나누는 과정에서 현재 로깅 방식에 아쉬움을 느끼게 되었다.

때문에 로깅 방식을 개선해보고자 몇 가지 고민을 했고, 그 과정과 결과를 기록해두고자 한다.

 

 

현재 Logging의 문제점

 

땅콩의 로그 형태

 

현재 우리 땅콩 서버의 로그는 다음과 같은 형태로 남겨지고 있다.

Request, Response에 대한 정보를 남기고 있는 효율적인 로깅 방식으로 보여진다.

 

하지만 여기에 하나의 문제점이 있다.

 

서버에 동시에 요청이 마구잡이로 들어왔을 때, 특정 로그를 어떻게 추적하여 확인할 수 있을까?

어떤 요청에서 예외가 발생했을 때, 빠른 속도로 어떤 요청에서 예외가 발생한 것인지 인지할 수 있을까?

 

본인은 지금 상태로는 사실상 굉장히 어려운 문제라고 생각했다.

 

때문에 이 문제를 해결하여 Observability를 개선해보고자 한다.

 

 

 

Observability란?

Observability는 소프트웨어 시스템의 상태를 외부에서 파악하고 이해할 수 있는 능력을 의미한다.

Observability는 아래 3가지 요소로 구분된다.

• 로그(logging): 시스템에서 발생하는 이벤트나 상태 변화를 기록한 정보. 각종 요청, 에러, 상태 변경 등과 같은 정보를 포함하며, 상세한 디버깅이나 시스템의 상태 파악에 도움을 준다.
• 메트릭(metrics): 시스템의 성능과 관련된 수치 데이터이다. CPU 사용률, 메모리 소비량, 요청 처리 시간, 오류 발생 횟수 등의 데이터를 수집하여, 시스템 성능을 모니터링하고 병목 현상이나 성능 저하를 탐지할 수 있다.
• 트레이싱(tracing): 개별 요청이나 트랜잭션이 시스템 내부에서 어떻게 처리되는지를 추적하는 방법이다. 여러 마이크로서비스나 애플리케이션 컴포넌트에서 요청이 어떤 경로를 통해 전달되는지 추적할 수 있어, 성능 문제나 오류가 발생한 지점을 파악하는 데 도움을 준다.

 

 

---

 

해결 방안

해결방안으로 떠올린 방법은 MDC를 사용하는 것이다.

요청이 도착했을 때, 각 요청마다 TraceID(UUID)를 생성하고, MDC에 삽입한다.

그리고 Log를 찍을 때 해당 정보를 함께 표시해준다.

 

그럼 요청별로 구분하는 것이 굉장히 쉽게 변할 것이라고 생각했다.

 

 

MDC (Mapped Diagnostic Context) 란?

MDC는 주로 로그 관리에서 사용하는 개념으로, 스레드 로컬(Thread Local) 변수를 통해 각 스레드별로 고유한 컨텍스트 데이터를 저장하고, 이를 로그에 포함시키는 기능을 제공한다.

 

스프링 부트와 같은 환경에서 요청 단위로 고유한 TraceID를 생성해 로그에 삽입할 때 자주 사용된다.

 

[MDC의 주요 기능]

• 스레드 별로 독립된 데이터를 관리할 수 있다. 이는 특히 멀티스레드 환경에서 유용하다.
• 특정 요청이나 작업에 관련된 메타데이터를 로그에 자동으로 삽입할 수 있다.
  예를 들어 TraceID, 사용자 ID, 세션 ID 등과 같은 정보를 로그 메시지에 포함할 수 있다.

 

만약 위와 같은 예외가 발생했을 때, 요청이 굉장히 많이 발생하고 있다면 어디서 예외가 발생한 건 지 어떻게 알 수 있을까?

지금은 DELETE 요청과 해당 요청에서 발생한 경고 로그가 붙어있지만, 굉장히 많은 요청이 들어오고 있는 와중에 저런 문제가 발생하면 오류의 원인을 로그에서 쉽게 찾아볼 수 있을까?

 

ThreadName으로 검색한다고 하더라도, Thread 는 ThreadPool에 한 번 등록된 Thread를 계속 재사용하기 때문에

검색한 ThreadName으로 처리된 굉장히 많은 작업 로그가 검색될 것이다.

내 생각엔 에러의 발생 원인 추적이 굉장히 복잡해질 것 같다고 생각한다.

 

 

이러한 상황에서 요청단위로 관리되는 TraceID(RequestID)를 사용하면, 위와 같이 문제 원인을 추척하기 수월해질 것이라고 생각했다.

한 눈에 들어오지 않는가?

 

 

---

 

구현하기

요청이 들어올 때 Controller Aspect 에서 MDC 사용하여 traceID 생성

@Slf4j
abstract class ControllerLoggingAspect {

    private static final String TRACE_ID_KEY = "traceId";

    //..PointCut 설정 중략

    protected void logControllerRequest(JoinPoint joinPoint) {
        setTraceId(); // TraceID 생성
        HttpServletRequest request = getHttpServletRequest();
        String uri = request.getRequestURI();
        String httpMethod = request.getMethod();
        String queryParameters = getQueryParameters(request);
        String body = getBody(joinPoint);

        log.info("Request Logging: {} {} body - {} parameters - {}", httpMethod, uri, body, queryParameters);
    }

    protected void logControllerResponse(JoinPoint joinPoint, Object responseBody) {
        HttpServletRequest request = getHttpServletRequest();
        String uri = request.getRequestURI();
        String httpMethod = request.getMethod();

        log.info("Response Logging: {} {} Body: {}", httpMethod, uri, responseBody);
        removeTraceId(); // TraceID 삭제
    }

		private void setTraceId() {
        String traceId = UUID.randomUUID().toString();
        MDC.put(TRACE_ID_KEY, traceId);
    }

    private void removeTraceId() {
        MDC.remove(TRACE_ID_KEY);
    }
    //.. 타 메서드 중략
}

위와 같이 setTraceId(), removeTraceId() 메서드를 바탕으로 MDC에 traceId를 생성 및 삭제 처리 해준다.

 

 

LogBack.xml 사용해서 traceID 남기기

<appender name="DDANGKONG_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/ddangkong.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/ddangkong-%d{yyyy-MM-dd}.log</fileNamePattern> <!-- 매일 새로운 파일 생성 -->
            <maxHistory>365</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss,Asia/Seoul} [%thread] %-5level %logger{36} [%X{traceId}] - %msg%n
            </pattern>
        </encoder>
</appender>

 

logback-{env}.xml 파일에서 로그 출력 패턴을 정하는 <pattern> 태그에

[%X{traceId}] 설정을 추가하여 MDC에 기록한 traceId를 출력하도록 만든다.

 

 

 

그럼 위와 같이 로그에 TraceID 가 함께 기록되기 시작한다.

 

 

요청/응답이 아닌 경우 TraceID 설정

 

그런데 위 로그에 문제가 있어보이지 않은가?

 

바로 요청/응답이 아닌 경우에 TraceID가 작성되지 않고 [] 로만 작성되는 문제인데, 이 문제도 해결해보자

위에서 설정해주었던 [%X{traceId}] 값 설정을 [%X{traceId:-NoTraceID}] 로 변경해주면 traceId가 없을 때 NoTraceID가 찍히게 된다.

 

 

 

이제 로그가 이렇게 위와 같이 표시된다.

깔끔하지 않은가?

 

 

---

 

결론

다수의 사람들이 서비스를 이용하는 우아한테크코스의 데모데이 직전, 모니터링이 수월하게 작동할 지 확인하는 과정에서 현재 로깅 방식에 아쉬움을 느꼈다. 로그를 요청 별로 구분해 줄 무언가가 필요하다고 느꼈다.

이를 해결하기 위해서 Thread Local을 사용하는 MDC를 사용하여 각 요청마다 TraceID를 갖도록 구성하고, 이를 로그 별로 함께 찍어줌으로써 로그 추적이 간편해지도록 구성할 수 있었다.

 

 

 

실제로 Toss의 SLASH 23에서도 위와 같은 주제를 다루었던 것을 검색 과정에서 알게 되었다.

기술적으로 훌륭한 실력을 가진 Toss에서도 고민했던 부분인 것을 확인하고 괜찮은 접근이라고 생각하였다.

자세히 알고 싶은 사람들은 위 영상을 시청하면 많은 도움이 될 것이라고 생각한다.