Spring WebFlux 기반 MDC 적용하기 (+코루틴)

MDC 란?

MDC 는 Mapped Diagnostic Context 의 약자로 key와 value를 저장하는 Map 형식으로 slf4j, logback, log4j 등 로깅 프레임워크에서 필요한 정보를 저장하고 싶을 때 사용한다.

ThreadLocal 을 기반으로 컨텍스트 정보를 저장하기 때문에 멀티 쓰레드 환경에서 유용하게 사용이 가능하다. (멀티 쓰레드 환경에서는 로그 메시지에 각 쓰레드에 대한 로그가 섞이기 때문)

요청이 어떤 사용자로부터 들어온 것인지 저장하거나 요청별로 식별자를 만들어 특정 요청에 대한 로그만 추적할 수 있다.

참고:

로그시스템 #4-MDC를 이용하여 쓰레드별로 로그 분류하기

MDC 적용하기

Spring Framework를 사용하고 있다면 AOP를 이용해 쉽게 적용이 가능하다.

implementation("org.springframework.boot:spring-boot-starter-web")
implementation("org.springframework.boot:spring-boot-starter-aop")

요청별로 식별자(traceId)를 저장하고 식별자를 통해 특정 요청에 대한 로그만 모아볼 수 있다.

요청에 대한 공통적 처리를 원한다면 아래와 같이 AOP를 사용하거나 Interceptor, Filter 등을 사용해 구현이 가능하다.

@Aspect
@Component
class MdcAspect {

    @Around("@annotation(RequestMapping)")
    fun setMdcTraceId(joinPoint: ProceedingJoinPoint): Any? {
        try {
            val traceId = UUID.randomUUID().toString()
            MDC.put("traceId", traceId)
            return joinPoint.proceed()
        } finally {
            MDC.remove("traceId")
        }
    }

아래와 같이 로그 설정 파일에 MDC에 저장한 key(traceId)를 찍어볼 수 있다.

<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} [traceId: %X{traceId}] - %msg%n</pattern>

 

비동기 환경에서는 어떻게 적용할 수 있을까?

하지만 비동기 환경이라면 조금 더 까다로워진다.

ThreadLocal에서 동작하는 MDC 특성상 하나의 쓰레드에서 여러개의 요청을 처리할 수 있는 비동기 환경이라면 MDC 정보가 유지되지 않을 수 있다.

즉, 하나의 요청을 처리할 때 쓰레드가 바뀌게 되면 MDC 정보가 유지되지 않을 수 있다.

현재 팀내에서 Spring WebFlux와 Armeria, Coroutine을 사용해 비동기 환경의 서버를 구현하고 있기 때문에 제대로 된 로그 추적을 위해서는 이에 대한 처리가 필요했다.

코루틴 스코프 내부의 스레드에도 MDC 정보를 넘겨주어야 했고 다행히도 코틀린은 MDCContext라는 로깅을 위한 코루틴 MDC 컨텍스트를 제공하고 있다.

MDCContext

코루틴 컨텍스트가 전환되는 부분에 아래와 같이 MDCContext를 추가하여 코루틴으로 전달되도록 할 수 있다.

withContext(Dispatchers.IO + MDCContext()){
	...
}

내부를 들여다보면 contextMap 이라는 Map 타입의 자료형 변수를 가지고 있다. 이 변수가 초기화될 때 외부의 MDC 컨텍스트를 가져와 저장하는 것을 볼 수 있다.

ThreadContextElement 인터페이스를 구현하고 있기 때문에 코루틴 컨텍스트로 사용이 가능하며 ThreadContext가 바뀔때마다 MDC 컨텍스트를 복사해주는 것을 볼 수 있다.

만약 코루틴 기반이 아닌 Mono와 Flux 기반 리액티브 타입을 사용하고 있다면 Reactor에서 제공하는 Context를 사용해 MDC를 복사하는 방법도 존재한다.

참고:

How can the MDC context be used in the reactive Spring applications | Novatec

Armeria ServiceRequestContext 이용하기

Armeria에서는 데코레이터를 사용해 Spring AOP와 같이 요청의 앞뒤로 공통 관심사를 분리해 코드를 작성해줄 수 있다.

사내에서 사용하고 있는 예전 서버들은 Spring Framework를 사용하고 있지 않기 때문에 Armeria Decorator를 사용해 API 요청이 들어올 때 MDC에 traceId 정보를 저장해주었다.

Armeria는 RequestContext를 제공한다. 호출하는 모든 요청에 대해 고유한 컨텍스트를 가지며 요청에 대한 다양한 정보를 가지고 있다. 이 컨텍스트의 id는 고유하기 때문에 traceId 로 적합하다.

하나의 요청에 대한 스레드가 바뀌더라도 이 컨텍스트는 유지되기 때문에 추적이 가능하다는 장점이 존재한다.

const val TRACE_ID = "traceId"

class MdcDecoratingService(delegate: HttpService) : SimpleDecoratingHttpService(delegate) {
    override fun serve(ctx: ServiceRequestContext, req: HttpRequest): HttpResponse {
        MDC.put(TRACE_ID, ctx.id().toString())

        val delegate = unwrap() as HttpService
        return delegate.serve(ctx, req)
    }
}

 

하지만 Armeria는 MDC에 직접 값을 넣어주지 않아도 RequestContextExportingAppender 라는 Logback Appender 를 제공한다. 이 appender를 사용하면 따로 처리를 해주지 않아도 안전하게 범용적으로 클라이언트 요청 정보를 추적할 수 있다.

Armeria에서 RequestContext는 위에서 말했던 것처럼 비동기환경에서도 요청별로 고유한 컨텍스트 정보를 가지고 있기 때문에 쓰레드가 수시로 바뀐다 하더라도 그대로 요청 정보를 유지할 수 있다. 

현재 처리중인 요청의 메타데이터들을 추출하거나 커스텀해서 정보들을 저장할 수 있는 Armeria에서 아주 중요한 컴포넌트 중 하나다.

 

RequestContextExportingAppender 는 현재 RequestContext 정보를 MDC로 내보내는 것이 가능한 appender이다.

아래와 같이 의존성을 추가해준 후,

dependencies {
    implementation platform('com.linecorp.armeria:armeria-bom:1.24.3')

    ...
    implementation 'com.linecorp.armeria:armeria-logback'
}

logback.xml에서 필요한 요청 정보를 export해 로그 메시지로 출력할 수 있다. 

    <appender name="LOG_FILE_INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/logback_info.log</file>
        <encoder>
            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} %-5level --- [%thread][traceId=%X{traceId}] %logger{36} [%F:%M:%line] : %msg%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
    </appender>

 

appender에서 요청별 로그 정보 추적을 위해 req.id를 export하여 traceId로 로그 메시지에 공통적으로 출력해주었다. 

    <appender name="RCEA" class="com.linecorp.armeria.common.logback.RequestContextExportingAppender">
        <export>traceId=req.id</export>
        <appender-ref ref="STDOUT" />
        <appender-ref ref="LOG_FILE_INFO"/>
    </appender>

 

이렇게 하면 굳이 데코레이터나 AOP로 MDC에 일일이 traceId를 저장해주지 않아도 로그에 필요한 MDC 정보를 출력할 수 있다. 

또한 비동기 환경에서 매번 컨텍스트가 바뀔 때 MDC를 관리해줄 필요도 없어 추가적인 추적 비용이 들지 않는다.

 

참고: 

https://easywritten.com/post/using-mdc-with-armeria/

 

요약

1. armeria 프레임워크를 사용하고 있다면 RequestContextExportingAppender 를 사용해보자. 

2. aremria와 같은 비동기 지원 프레임워크를 사용하고 있지 않다면 WebFilter를 사용해 모든 요청에 MDC 정보를 유지하도록 적용

 

WebFilter에 적용할 로직은 아래 2가지 중 선택할 수 있다.

  1) Reactor 기반 : CoreSubscriber  를 구현해 onNext 메서드에 MDC 유지되도록 세팅

  2) Coroutine 기반 : ThreadContextElement 를 구현해 컨텍스트에 MDC 복사 로직 세팅 OR MDCContext 사용