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를 따라가면 로그를 확인하기 쉬워진다.