WebFlux에서 MDC 사용하기 - SpringBoot 2 버전

1. 개요 - MDC의 리액티브에서의 한계점

MDC(Mapped Diagnositc Context)는 클라이언트 요청에 대한 유니크한 값을 로그 컨텍스트에 담아 어느 위치에서든 해당 데이터에 대한 로깅이 가능하도록 지원합니다.

MDC는 내부적으로 ThreadLocal을 통하여 메타데이터를 관리하는데, 이는 SpringMVC와 같이 하나의 요청을 하나의 스레드에서 수행하는(thread-per-request) 구조에서 정상적으로 동작합니다.

하지만 Event Loop 방식으로 동작하는 Spring WebFlux에서는 하나의 요청에 대하 여러 스레드에서 수행될 수 있기에, MDC를 통하여 로깅하는것은 불가능합니다.

Spring MVC에서의 방식을 명령형 프로그래밍 방식, WebFlux의 방식을 리액티브 프로그래밍 방식이라 합니다. 우리는 이 두 방식에 따라 스레드를 다르게 다루어야할 필요가 있습니다.

이번 글에서는 리액티브 프로그래밍 방식으로 MDC를 사용하는 방법에 대해서 정리하였습니다.

1.1. Reactor Context

Reactor 3.1.0 부터 Reactor는 Flux나 Mono에서 ThreadLocal 처럼 동작할 수 있는 Context를 제공합니다.

Context는 operator 체인에 따라 전파되며, Context를 생성하기 위해서는 contextWrite operator를 사용하여야 합니다. 이 외에 Context에 대한 내용이 궁금하시면 이 링크를 확인해보시기 바랍니다.

정리하면, ThreadLocal의 역할을 리액티브 프로그래밍 방식에서는 Context가 수행할 수 있습니다.

2. Reactor With MDC (springboot 2)

Reactor 환경에서 MDC를 사용하기 위해서는 몇가지 설정이 필요합니다. 이미 온라인에도 많이 소개된 코드이므로 설명만 함께 추가하겠습니다.

설정

/**
 * Reactor 스코프에서 Reactor.Context의 상태를 MDC 로 복사해 주기 위한 설정
 */
@Configuration
public class MdcContextLifterConfiguration {

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

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

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

	/**
	 * onNext 호출 시 Reactor.Context 상태를 MDC로 복사해주는 Helper
	 * @param <T>
	 */
	public static class MdcContextLifter<T> implements CoreSubscriber<T> {
		private final CoreSubscriber<T> coreSubscriber;

		public MdcContextLifter(CoreSubscriber<T> coreSubscriber) {
			this.coreSubscriber = 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();
		}

		/**
		 * Context를 MDC로 복사한다.
		 * Context가 비어있을 시 MDC를 clear한다
		 * 이 메서드가 호출된 후 MDC의 상태는 Reactor.Context와 동일해진다.
		 */
		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();
			}
		}
	}
}

MdcContextLifter Subscriber의 데코레이터처럼 기본 동작을 래핑하고 있습니다. 이 구현에서 살펴보아야 할 메서드는 onNext와 currentContext 입니다.

• onNext : coreSubscriber의 Context를 가져와 MDC에 세팅합니다
• currentContext : coreSubscriber의 Context를 반환하도록 합니다.

Hooks.onEachOperator(MDC_CONTEXT_REACTOR_KEY, Operators.lift((scannable, subscriber) -> new MdcContextLifter<>(subscriber)));

Hooks.onEachOperator는 Mono/Flux로 생성된 operator에 대하여 적용할 Publisher 대한 커스터마이징을 지원합니다. 여기서는 기본 subscriber를 MdcContextLifter로 wrapping 하도록 합니다. 이 설정을 통해 onNext 마다 Context의 내용을 MDC로 덮어쓰도록 하여 로깅에 필요한 메타데이터를 스레드마다 유지하도록 합니다.

ContextWrite

@Component
public class MdcFilter implements WebFilter {

	@Override
	public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {
		return chain.filter(exchange)
				.contextWrite(context -> Context.of("requestId", String.valueOf(Math.round(Math.random() * 100000000))));
	}
}

명령형 프로그래밍 방식이라면 인터셉터에서 사용자에 대한 인증을 처리하거나 요청에 대한 고유한 식별자를 MDC에 세팅할 것입니다. WebFlux에서는 인터셉터의 역할을 WebFilter가 수행합니다. 위 코드는 WebFliter를 생성하고 요청에 대한 식별자를 contextWrite operator를 통해 Context에 등록합니다.

Context의 데이터는 MdcContextLifterConfiguration 설정으로 인해 다른 operator가 수행될 때 해당 operator를 수행하는 스레드의 MDC로 덮어쓰여집니다.

logback

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] [%-5p] [%X{requestId}] \(%logger{10}:%L\) %m%n</pattern>
  </encoder>
</appender>

MDC에 설정 규칙에따라 %X{requestId} 를 패턴으로 등록하여 MDC의 requestId 값을 로깅에 포함되도록 하였습니다.

3. MDC in ExceptionHandler

WebFlux로 서비스를 구축하면 글로벌 에러 처리를 위해 ErrorWebExceptionHandler 클래스를 구현하여 빈으로 등록합니다. 일반적으로 DefaultErrorWebExceptionHandler 클래스를 상속하고, 필요한 메서드만 오버라이드 합니다. 이 중 logError 메서드를 오버라이드 한다면 에러 발생 시 출력할 로그 메시지를 커스터마이징할 수 있습니다. 하지만 이 곳에서는 MDC 데이터가 전파되지 않는 이슈가 존재합니다.

3.1. 원인 분석

@Override
public Mono<Void> handle(ServerWebExchange exchange, Throwable throwable) {
	if (exchange.getResponse().isCommitted() || isDisconnectedClientError(throwable)) {
		return Mono.error(throwable);
	}
	this.errorAttributes.storeErrorInformation(throwable, exchange);
	ServerRequest request = ServerRequest.create(exchange, this.messageReaders);
	return getRoutingFunction(this.errorAttributes).route(request).switchIfEmpty(Mono.error(throwable))
			.flatMap((handler) -> handler.handle(request))
			.doOnNext((response) -> logError(request, response, throwable))
			.flatMap((response) -> write(exchange, response));
}

위의 코드는 AbstractErrorWebExceptionHandler#handle 메서드 입니다. handle 메서드는 에러를 핸들링하는 메서드이며, 이곳에서 logError 를 메서드 호출합니다. 디버깅으로 MDC 값을 확인하였으나 값들이 잘 들어있음을 확인할 수 있었습니다.

handle 메서드 첫라인에서는 MDC가 정상적으로 들어가있음을 확인할 수 있습니다.

그렇다면 왜 logError 에서는 MDC 값이 출력되지 않았을까요?

체인을 자세히 살펴보면 getRoutingFunction(this.errorAttributes) 로 부터 시작되어 체이닝을 통해 logError 메서드가 호출됩니다. getRoutingFunction 메서드는 RoutingFunction 타입을 반환하며, 내부적으로 accept 헤더를 통해 에러에 대한 응답을 html 또는 json으로 내려줄지를 판단하고 렌더링할 메서드로 라우트합니다.

디버깅한 결과 이곳에서의 Context는 비어있는 상태로 보이는데, RoutingFunction을 통해 새롭게 라우트되었기에 Context가 초기화된것으로 보입니다.

logError 처리 시 MDC 데이터가 복사되지 못한것으로 확인됩니다.

3.2. 해결 방법

정리하면, handle 메서드에서 getRoutingFunction 메서드 라인을 기준으로 위는 Context가 이어져서 MDC 데이터도 유지가 되는 반면, 아래 라인은 Context의 초기화로 MDC 데이터가 비어있는 상태입니다.

@Override
public Mono<Void> handle(ServerWebExchange exchange, Throwable throwable) {
	return super.handle(exchange, throwable)
			.contextWrite(Context.of(MDC.getCopyOfContextMap()));
}

handle 메서드를 오버라이드하여 래핑하여 구현하며 반환하는 Mono에 대하여 추가적으로 contextWrite 을 통해 MDC의 내용을 Context에 덮어씁니다. contextWrite 설정을 통해 getRoutingFunction 이후 handle, logError, write 를 처리하는 내부 시퀀스에도 MDC 데이터가 세팅된 Context가 전파되며, 앞서 설정한 훅 설정이 동작하여 logError 메서드 호출 시 MDC 값이 유지되게 됩니다.

contextWrite를 통해 MDC를 Context로 전달하자 logError 호출 시에도 MDC가 복사됨이 확인됩니다.

4. 정리 및 단점

리액티브 프로그래밍 방식의 Spring WebFlux 는 하나의 요청에 대하여 여러 스레드가 동작하기 때문에 MDC를 사용하기 어렵습니다. 이는 Reactor Context를 이용하여 해결할 수 있습니다. MDC 데이터를 Context에서 관리하도록 하며 훅 과 Publisher 설정을 통해 각 operator 마다 Context로 부터 MDC 읽어 들여와 유지시켜줄 수 있다면 리액티브 환경에서도 로깅 시 MDC 기능을 사용할 수 있습니다.

하지만 단점도 존재하였습니다. 에러를 함께 출력하면 stack trace에 MdcContextLifterConfiguration 클래스의 로그가 무더기로 쌓인것을 확인할 수 있는데요, 아무래도 직접 설정을 추가하여 MDC를 복사해주는 클래스를 직접 추가하니, 에러 원인을 파악하는데 도움이 되지 않는 로그가 강조되어 남고있음을 확인할 수 있었습니다.

Reactor 3.5.0 이후로는 내부적으로 MDC와 같은 ThreadLocal을 다른 스레드에서도 유지될 수 있도록 하는 설정이 존재합니다. 이를 설정하는 방법과 예시 코드에 대해서는 다음 글에 이어서 정리하도록 하겠습니다.

감사합니다.

5. 참고 자료

• https://logback.qos.ch/manual/mdc.html
• https://www.novatec-gmbh.de/en/blog/how-can-the-mdc-context-be-used-in-the-reactive-spring-applications/
• https://spring.io/blog/2023/03/30/context-propagation-with-project-reactor-3-unified-bridging-between-reactive