서버 애플리케이션을 개발하다보면 서버로 들어온 하나의 고유한 HTTP 요청에 대한 context 정보(대표적으로 로깅)를 여러 스레드에 걸쳐서 공유하고 유지해야할 필요가 생깁니다.
가령 HTTP 요청마다 고유의 TraceID 를 할당하고 추후 디버깅할 때 이 TraceID 로 로깅 저장소에서 관련 로그를 필터링해서 로그를 추적하기 쉽게 하는데 활용할 수 있습니다.
그래서 위에서 언급한 TraceID 와 같은 context 정보를 요청마다 할당하고 관리하는 작업을 자동화하기 위해 나온 라이브러리가 많습니다. JAVA 계열의 로깅 라이브러리(slf4j, logback, log4j2…)들은 이를 위한 기능이 보통 탑재되어있는데, 이를 MDC(Mapped Diagnostic Context) 라고 부릅니다.
하지만 여러 스레드를 활용하는 코드에서 context 정보를 유지하려면 추가적인 작업이 필요합니다.
예시를 위해 위처럼 간단한 API 를 하나 만들고 로그를 찍어봤습니다.
로그 화면에서 제가 빨간색으로 표시한 부분을 보면 난수처럼 보이는 문자열이 두개 보입니다. 왼쪽부터 각각 Trace ID, Span ID 입니다. 보통 요청 단위 ID 를 Trace ID, 기능 단위 ID 를 Span ID 라고 부릅니다. 그래서 요청을 새롭게 생성하면 다른 ID 가 보이죠.
아까 설명했던 로깅 라이브러리를 사용하면 이런 Context 정보를 자동으로 생성하고 관리해줍니다.
하지만 이 라이브러리의 손이 닿지 않는 곳이 있는데요, 그 중 하나가 코루틴입니다. 먼저 코드부터 봅시다.
아까 봤던 코드에 코루틴 관련 코드를 조금 추가했습니다. runBlocking 으로 코루틴 스코프를 하나 만들고 안에 suspend function을 호출하고 로그를 몇줄 남겼습니다. 이 코드를 실행해보면,
코루틴 스코프 내부에서 찍은 로그에는 Trace ID, Span ID 에 대한 정보가 없습니다. 아무래도 라이브러리가 코루틴 내부까지 context 정보를 전달해주지는 않는 모양입니다.
해결방법은 의외로 간단합니다. 이미 여러 스레드간 Tracing 정보를 공유하려는 시도는 아주 오래전부터 있었고 솔루션도 존재합니다. 한줄로 요약하면 MDC 를 사용해서 context 정보를 스레드간에 공유하는겁니다. 자세한 내부 구현은 일단 생략하고 솔루션 코드부터 보겠습니다.
우선 gradle 에 라이브러리를 추가해주고,
문제의 코드를 아래처럼 수정합니다.
코드를 실행하면 아까와는 달리 Tracing 정보가 코루틴 내부까지 공유된걸 볼 수 있습니다.
MDC
먼저 MDC 가 정확히 무엇을 의미하는지 짚고 넘어갑시다.
‘스레드별로 특정 ID를 할당해서 로깅 트레이싱 추적을 용이하게 하자’ 는 아이디어는 너무 좋지만 이를 어떻게 구현할까요? 당장 떠오르는 무식한 생각은 호출하는 메소드마다 파라미터로 다 넣는 방식인데 비효율적이고 번거롭죠. 그래서 자바의 ThreadLocal 이라는 도구를 활용합니다. ThreadLocal 이란 한 스레드의 생명주기 내에서 공유하여 사용할 수 있는 변수입니다. 그래서 서버로 요청이 들어왔을 때 해당 스레드의 ThreadLocal 에 TraceID 를 생성해서 저장하고 필요할 때 꺼내서 쓰면 되겠죠.
그리고 이 ThreadLocal 이라는 도구를 활용해 로깅과 트레이싱이라는 use-case 에 맞게 추상화한 도구가 바로 MDC(Mapped Diagnostic Context) 입니다.
위에서 봤던 스크린샷에서 제가 별도의 작업을 하지 않았는데도 로그마다 각 요청의 고유한 TraceID 가 같이 출력됐었죠. logback 이 내부적으로 MDC 를 사용해서 요청마다 TraceID 를 생성하고 관리해주고 있기 때문에 가능했습니다. MDC 가 아니었다면 매번 로깅이 필요할 때 마다 ThreadLocal 에 context 정보를 넣었다 뺐다 해야하는데 여간 번거로운 작업이 아니죠.
물론 MDC 에는 logback 이 저장하는 context 데이터와 별개로 개발자가 원하는 다른 데이터도 저장할 수 있습니다. (MDC.put(), MDC.get())
Coroutine MDCContext
하지만 위에서 보신 것 처럼 코루틴 스코프 내부에서 출력한 로그는 TraceID 가 비어있습니다. 코루틴 스코프 내부의 코드는 별도의 스레드에서 실행되고, MDC는 생명주기가 하나의 스레드에 한정되어있으니 당연한 결과이기도 합니다. 이 문제는 어떻게 해결하면 좋을까요? MDC에 관한 정보를 코루틴 내부로, 정확히는 해당 코루틴이 실행될 스레드로 넘겨주면 될 것 같은데… Dispatcher 는 별도의 스레드풀을 관리하니 벌써 머리가 아픕니다.
다행히도 코틀린은 이를위해 MDCContext 라는 유용한 도구를 이미 만들어놓았습니다. 사용법은 간단합니다. 위에서 본 것 처럼 코루틴 스코프 선언시에 같이 넣어주면됩니다.
MDC.put("kotlin", "rocks") // Put a value into the MDC context
launch(MDCContext()) {
logger.info { "..." } // The MDC context contains the mapping here
}MDCContext 내부
MDCContext 는 어떻게 외부 스레드의 MDC 를 코루틴이 실행될 스레드로 넘겨주는걸까요? 궁금하니 코드를 까봅시다.
내부적으로 contextMap 이라는 map 자료형 변수를 하나 가지고있는 짧은 클래스네요.
MDC.getCopyOfContextMap() 메소드로 MDCContext 인스턴스가 생성될 시점에 외부 스레드의 MDC 정보를 가져와서 저장합니다. 그리고 CoroutineContext.Element 인터페이스를 구현하니 CoroutineContext 로 사용가능합니다.
코루틴 내부에서 스레드 전환시에 updateThreadContext() 메소드가 반드시 호출될텐데 위 MDCContext 클래스에서 오버라이드 한 동작을 보면 contexMap 변수를 교체해주고있죠.
결과적으로 MDC 에 관한 정보는 CoroutineContext 내부에 저장되고 CoroutineContext 는 특정 스레드에 종속되지 않으니 코루틴 내부에서 스레드 전환시에 적절히 주입해줄 수 있었습니다.
