MDC를 이용한 로깅 도입기

로깅을 왜 해야 할까?

운영 서버에서 항상 문제가 발생하지 않기를 바라지만, 이는 매우 어려운 일입니다. 시스템이 복잡해질수록 문제는 더 자주 발생할 수 있고, 이를 해결하기 위해서는 로그가 필수적입니다. 로그는 단순한 기록이 아니라, 시스템의 행동을 이해하고 문제를 추적하는 데 있어 개발자와 운영팀의 비밀 무기입니다.

 

예를 들어, 한 사용자가 웹 애플리케이션에서 특정 기능을 사용하다가 오류를 경험했다고 가정해 봅시다. 문제를 해결하기 위해 개발자는 로그를 확인하려고 합니다. 하지만 로그가 명확한 정보 없이 단순히 "오류 발생"이라고만 적혀 있다면, 어떤 상황에서 문제가 발생했는지, 어떤 사용자가 영향을 받았는지를 파악하기가 매우 어렵습니다. 이런 상황에서 개발자는 로그를 해석하는 데 많은 시간을 소모하고, 사용자에게는 불편함을 주게 됩니다.

 

현재 로컬에선

현재 로컬 환경에서는 간단하게 콘솔로 로그를 출력하고 있습니다. 이는 개발 과정에서 문제를 빠르게 파악하는 데 유용하지만, 실제 운영 환경에서는 더 많은 정보가 필요합니다. 운영 서버에서는 다양한 이벤트를 체계적으로 기록하여, 사용자에게 영향을 줄 수 있는 문제를 즉시 파악할 수 있어야 합니다.

 

필요한 로그 정보

운영 서버에서 저는 다음과 같은 정보들이 포함된 로그를 구현하고자 합니다.

• 에러 및 경고 기록 : 사용자에게 영향을 줄 수 있는 문제를 즉시 파악하기 위해 필요합니다.
• 트랜잭션 흐름 : 요청이 시스템을 어떻게 흐르는지 이해하고, 문제 발생 시 빠르게 대응할 수 있도록 하려고 합니다.

 

그럼 어떻게 운영 서버에서 정보들을 출력할 수 있을까?

이를 위해 MDC(Mapped Diagnostic Context)라는 기능을 도입하였습니다. MDC는 각 스레드에 대한 추가적인 정보를 기록할 수 있는 기능으로, 로그 메시지에 사용자 정의 정보를 첨부할 수 있습니다. 예를 들어, 각 요청에 대한 고유한 ID를 포함시키거나, 사용자 정보 등을 기록할 수 있어 로그 분석 시 매우 유용합니다.

 

MDC의 필요성

예를 들어, 운영 중인 시스템에서 여러 사용자가 동시에 요청을 보내고 있다고 가정해 봅시다. 이때 특정 사용자의 요청이 오류를 일으킨다면, 해당 요청의 흐름을 추적하는 것이 중요합니다. 하지만 만약 로그에 이 요청의 ID나 어떤 메서드가 호출되었는지에 대한 정보가 없다면, 문제를 찾아내는 데 많은 시간이 소모될 것입니다. 하지만 MDC를 활용하면 각 요청에 대한 고유한 ID를 기록하고, 요청이 어떤 컨트롤러와 메서드에서 처리되었는지를 명확히 할 수 있습니다. 

 

운영 서버의 Logback 설정

현재 운영 서버에서는 Logback을 사용하여 다음과 같이 로그를 설정하고 있습니다.

<springProfile name="prod">
        <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
        <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>logs/info/info.log</file>
            <filter class="ch.qos.logback.classic.filter.LevelFilter">
                <level>INFO</level>
                <onMatch>ACCEPT</onMatch>
                <onMismatch>DENY</onMismatch>
            </filter>
            <encoder>
                <pattern>%d{HH:mm:ss.SSS} [%X{request_id}] [%X{controller}] [%X{method}] [%thread] %-5level %logger{36} - %msg%n</pattern>
                <charset>utf8</charset>
            </encoder>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern>logs/info/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>
        <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>logs/warn/warn.log</file>
            <filter class="ch.qos.logback.classic.filter.LevelFilter">
                <level>WARN</level>
                <onMatch>ACCEPT</onMatch>
                <onMismatch>DENY</onMismatch>
            </filter>
            <encoder>
                <pattern>%d{HH:mm:ss.SSS} [%X{request_id}] [%X{controller}] [%X{method}] [%thread] %-5level %logger{36} - %msg%n</pattern>
                <charset>utf8</charset>
            </encoder>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern>logs/warn/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>
        <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>logs/error/error.log</file>
            <filter class="ch.qos.logback.classic.filter.LevelFilter">
                <level>ERROR</level>
                <onMatch>ACCEPT</onMatch>
                <onMismatch>DENY</onMismatch>
            </filter>
            <encoder>
                <pattern>%d{HH:mm:ss.SSS} [%X{request_id}] [%X{controller}] [%X{method}] [%thread] %-5level %logger{36} - %msg%n</pattern>
                <charset>utf8</charset>
            </encoder>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern>logs/error/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>

위 설정에서는 INFO, WARN, ERROR 로그만 기록하도록 설정하였습니다. request_id, controller, method를 통해 사용자가 어떤 흐름으로 요청을 처리했는지를 쉽게 알 수 있습니다.

 

적용 코드

MDC는 필터, 인터셉터등 앞단에 넣는 게 좋은데, 저는 인터셉터에서 다음과 같이 작업을 수행하도록 설정하였습니다.

@Override
    public boolean preHandle(final HttpServletRequest request, HttpServletResponse response, Object handler) {
        if (CorsUtils.isPreFlightRequest(request)) {
            return true;
        }
        UUID uuid = UUID.randomUUID();
        MDC.put("request_id", uuid.toString());

        if (handler instanceof HandlerMethod) {
            HandlerMethod handlerMethod = (HandlerMethod) handler;
            String controllerName = handlerMethod.getBeanType().getSimpleName();
            String methodName = handlerMethod.getMethod().getName();
            MDC.put("controller", controllerName);
            MDC.put("method", methodName);
        }

        final String token = AuthorizationExtractor.extract(request);
        jwtProvider.getPayload(token);
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        MDC.clear();
    }

여기서 주의해야 할 점은, 꼭 clear를 해줘야 합니다. Spring MVC는 스레드 풀에 스레드들을 만들어 두고, 요청이 오면 스레드를 사용해 요청을 처리하고 반납합니다. 그런데 MDC는 스레드 별로 저장되는 스레드 로컬을 사용하므로, 요청이 완료될 때 clear를 해주지 않으면 다른 요청이 이 스레드를 재사용할 때 이전 데이터가 남아있을 수 있기 때문입니다.

 

결과

이를 통해 각 로그는 발생 시점, 요청의 고유 식별 번호, 어떤 컨트롤러 및 메서드에서 호출되었는지를 명확히 보여주며, 문제가 발생했을 때 로그를 신속하게 추적하고 해결하는 데 도움이 될 것입니다.