MDC(Mapped Diagnostic Context)

MDC는 로그를 더 잘 추적할 수 있도록 하는 정보를 로그 메세지에 찍을수있게 해주는 기능을 한다.

Map으로 되있으며 ThreadLocal 사용으로 인해 Thread 단위로 생성된다.

Slf4j MDC를 사용 기준으로 org.slf4j.MDC 클래스 안에 static으로 선언된 MDCAdapter 를 찾아 볼 수 있다.

MDCAdapter는 인터페이스로 되있는데 Adapter를 implements 하는 클래스를 찾아 보면 LogbackMDCAdapter 가 보인다.

여기에 보면

public class LogbackMDCAdapter implements MDCAdapter {
    ...
    final ThreadLocal<Map<String, String>> copyOnThreadLocal = new ThreadLocal<Map<String, String>>();
    ...
}

이렇게 ThreadLocal로 선언된 걸 찾을 수 있다.

Logback 설정하기

MDC를 사용하기 위해서는 Logback 설정이 필요하다.

이 설정은 Spring WebFlux 기준 이다.

application.yml

logging:
  config: classpath:logback/logback.xml

logback.xml

logback.xml에서는 MDC에서 설정한 값을 사용하려고 한다.

설정한 값을 사용하기 위해 [%X{uuid}]라는 값을 밑의 설정 파일에 명시해 둔 것을 확인할 수 있다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <property name="LOG_DIR" value="../" />

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                [%-5level] [%thread] [%X{uuid}] %d{yyyy-MM-dd HH:mm:ss.SSS} : %30logger{5} - %msg%n
            </Pattern>
        </layout>
    </appender>
    
    <appender name="SYSLOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/syslog/syslog.log</file>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                [%-5level] [%thread] [%X{uuid}] %d{yyyy-MM-dd HH:mm:ss.SSS} : %30logger{5} - %msg%n
            </Pattern>
        </layout>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/syslog/syslog.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>
    
    <appender name="ACCESSLOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_DIR}/accesslog/accesslog.log</file>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                [%thread] [%X{uuid}] %msg%n
            </Pattern>
        </layout>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/accesslog/accesslog.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="SYSLOG" />
    </root>
    <logger name="kr.springboot.mdc" level="debug" additivity="false">
        <appender-ref ref="CONSOLE" />
    </logger>
    <logger name="access-log" level="info" additivity="false">
        <appender-ref ref="ACCESSLOG" />
    </logger>


</configuration>

Spring WebFlux MDC 설정 하기

WebFilter

필터에서는 들어오는 요청의 쓰레드에 MDC를 설정할 수 있다.

package kr.springboot.mdc.filter;

import org.slf4j.MDC;
import org.springframework.web.server.ServerWebExchange;
import org.springframework.web.server.WebFilter;
import org.springframework.web.server.WebFilterChain;
import reactor.core.publisher.Mono;
import reactor.util.context.Context;

import java.util.UUID;

public class MdcLoggingFilter implements WebFilter {

    private static final String MDC_UUID = "uuid";

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
        return chain.filter(exchange).contextWrite(context -> {
            final String uuid = UUID.randomUUID().toString();
            MDC.put(MDC_UUID, uuid);
            return Context.of(MDC_UUID, uuid);
        });
    }

}

@Configuration

여기서 MDC에서 설정 한 값을들 초기화 하기 위해 copyToMdc Method에서 Clear를 하는 것을 볼 수 있다.

package kr.springboot.mdc.config;

import kr.springboot.mdc.filter.MdcLoggingFilter;
import lombok.RequiredArgsConstructor;
import org.reactivestreams.Subscription;
import org.slf4j.MDC;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import reactor.core.CoreSubscriber;
import reactor.core.publisher.Hooks;
import reactor.core.publisher.Operators;
import reactor.util.context.Context;

import javax.annotation.PostConstruct;
import javax.annotation.PreDestroy;
import java.util.Map;
import java.util.stream.Collectors;

/**
 * @link https://www.novatec-gmbh.de/en/blog/how-can-the-mdc-context-be-used-in-the-reactive-spring-applications/
 */
@Configuration
public class MdcContextLifterConfiguration {

    public static final String MDC_CONTEXT_REACTOR_KEY = MdcContextLifterConfiguration.class.getName();

    @PostConstruct
    @SuppressWarnings("unchecked")
    public void contextOperatorHook() {
        Hooks.onEachOperator(MDC_CONTEXT_REACTOR_KEY, Operators.lift((scannable, subscriber) -> new MdcContextLifter(subscriber)));
    }

    @Bean
    public MdcLoggingFilter mdcLoggingFilter() {
        return new MdcLoggingFilter();
    }

    @PreDestroy
    public void cleanupHook() {
        Hooks.resetOnEachOperator(MDC_CONTEXT_REACTOR_KEY);
    }

    /**
     * Helper that copies the state of Reactor [Context] to MDC on the #onNext function.
     */
    @RequiredArgsConstructor
    public static class MdcContextLifter<T> implements CoreSubscriber<T> {

        private final CoreSubscriber<T> coreSubscriber;

        @Override
        public void onSubscribe(Subscription subscription) {
            coreSubscriber.onSubscribe(subscription);
        }

        @Override
        public void onNext(T t) {
            copyToMdc(coreSubscriber.currentContext());
            coreSubscriber.onNext(t);
        }

        @Override
        public void onError(Throwable throwable) {
            coreSubscriber.onError(throwable);
        }

        @Override
        public void onComplete() {
            coreSubscriber.onComplete();
        }

        @Override
        public Context currentContext() {
            return coreSubscriber.currentContext();
        }

        /**
         * Extension function for the Reactor [Context]. Copies the current context to the MDC, if context is empty clears the MDC.
         * State of the MDC after calling this method should be same as Reactor [Context] state.
         * One thread-local access only.
         */
        void copyToMdc(Context context) {
            if (context != null && !context.isEmpty()) {
                Map<String, String> map = context.stream()
                        .collect(Collectors.toMap(e -> e.getKey().toString(), e -> e.getValue().toString()));
                MDC.setContextMap(map);
            } else {
                MDC.clear();
            }
        }
    }
}

확인하기

모든 설정이 끝났다면 한번 확인해보자.

예제는 http 요청을 하는 예제로 설정 전 로그는 다음과 같다.

2022-09-04 19:57:30.184  INFO 80170 --- [ctor-http-nio-3] k.springboot.mdc.service.MdcTestService  : MonoLiftFuseable
2022-09-04 19:57:30.597 DEBUG 80170 --- [ctor-http-nio-3] r.netty.http.client.HttpClientConnect    : [ec54d609-1, L:/192.168.0.102:56393 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Handler is being applied: {uri=https://jsonplaceholder.typicode.com/todos/1, method=GET}
2022-09-04 19:57:30.668 DEBUG 80170 --- [ctor-http-nio-3] r.n.http.client.HttpClientOperations     : [ec54d609-1, L:/192.168.0.102:56393 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Received response (auto-read:false) : [Date=Sun, 04 Sep 2022 10:57:32 GMT, Content-Type=application/json; charset=utf-8, Transfer-Encoding=chunked, Connection=keep-alive, X-Powered-By=Express, X-Ratelimit-Limit=1000, X-Ratelimit-Remaining=998, X-Ratelimit-Reset=1661768056, Vary=Origin, Accept-Encoding, Access-Control-Allow-Credentials=true, Cache-Control=max-age=43200, Pragma=no-cache, Expires=-1, X-Content-Type-Options=nosniff, Etag=W/"53-hfEnumeNh6YirfjyjaujcOPPT+s", Via=1.1 vegur, CF-Cache-Status=HIT, Age=212, Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=VHZ%2FwY%2BQiIfRRLg5C3uCqwdSSrFXtNQxmXjyt5H%2BXaHYGdJvYCILHF93IOQ3WZ47SO1oQ3Jprb9%2B5wkSD2qRBiX9%2BugQ8LmGFBFtFph%2BVsnPM1XYeH%2Bn04NhHvGLh8z5LDoazC1MrjROk1h5suPb"}],"group":"cf-nel","max_age":604800}, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Server=cloudflare, CF-RAY=74563473a915b46a-HKG, alt-svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400]
2022-09-04 19:57:30.691 DEBUG 80170 --- [ctor-http-nio-3] r.n.http.client.HttpClientOperations     : [ec54d609-1, L:/192.168.0.102:56393 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Received last HTTP packet

[INFO ] [reactor-http-nio-3] [4e3955e6-5206-4def-ab71-92e71e36d490] 2022-09-04 19:59:39.895 :         k.s.m.s.MdcTestService - MonoLiftFuseable
[DEBUG] [reactor-http-nio-3] [4e3955e6-5206-4def-ab71-92e71e36d490] 2022-09-04 19:59:40.771 :      r.n.h.c.HttpClientConnect - [ef905c50-1, L:/192.168.0.102:56408 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Handler is being applied: {uri=https://jsonplaceholder.typicode.com/todos/1, method=GET}
[DEBUG] [reactor-http-nio-3] [4e3955e6-5206-4def-ab71-92e71e36d490] 2022-09-04 19:59:40.866 :   r.n.h.c.HttpClientOperations - [ef905c50-1, L:/192.168.0.102:56408 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Received response (auto-read:false) : [Date=Sun, 04 Sep 2022 10:59:42 GMT, Content-Type=application/json; charset=utf-8, Transfer-Encoding=chunked, Connection=keep-alive, X-Powered-By=Express, X-Ratelimit-Limit=1000, X-Ratelimit-Remaining=998, X-Ratelimit-Reset=1661768056, Vary=Origin, Accept-Encoding, Access-Control-Allow-Credentials=true, Cache-Control=max-age=43200, Pragma=no-cache, Expires=-1, X-Content-Type-Options=nosniff, Etag=W/"53-hfEnumeNh6YirfjyjaujcOPPT+s", Via=1.1 vegur, CF-Cache-Status=HIT, Age=342, Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=sUgBVCk8BU2qNiYJR7r7Dnf%2FlH87NAt8NWnHDj2KgiVFL%2Fc6OMFFGUhJnEy5vBize%2F%2BMLuwJIkGpKmHrRz%2Bs%2FE%2B22b6wilr6XFjQyTiFNdzWHQSVVgQYG1asn0oXHOlsqdHwTzQBzX7%2BT6vp9rUF"}],"group":"cf-nel","max_age":604800}, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Server=cloudflare, CF-RAY=745637a159013d76-HKG, alt-svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400]
[DEBUG] [reactor-http-nio-3] [4e3955e6-5206-4def-ab71-92e71e36d490] 2022-09-04 19:59:40.913 :   r.n.h.c.HttpClientOperations - [ef905c50-1, L:/192.168.0.102:56408 - R:jsonplaceholder.typicode.com/104.21.4.48:443] Received last HTTP packet

설정한 대로 쓰레드 옆에 UUID의 값이 찍히는 것을 확인할 수 있다.

UUID를 따라가면 로그를 확인하기 쉬워진다.

REFERENCE

https://www.novatec-gmbh.de/en/blog/how-can-the-mdc-context-be-used-in-the-reactive-spring-applications/