Armeria에서 MDC를 사용해도 될까?

MDC를 그냥 쓰면 안된다

멀티스레드 프로그램에서 여러 스레드가 동시에 요청을 처리할 때 각자 남긴 로그는 컨텍스트 스위칭 때문에 섞여 알아보기 어려워집니다. 이를 해결하기 위해 요청에 ID를 부여하여 같은 ID를 가진 로그들을 묶어서 그 요청에 대한 로그만 볼 수 있습니다. 아이디어를 구현하기 위해 요청을 시작할 때 ID를 생성한 후 지나가는 모든 메소드에 ID를 인자로 넘겨서 로깅에 사용하는 방법이 있습니다. 하지만 이는 너무 번거롭기 때문에 하나의 요청을 한 스레드가 처리한다는 점에서 착안해 자바의 ThreadLocal을 사용해 ID를 저장해놓고 로깅할 때 꺼내쓰면 훨씬 깔끔하게 코드를 작성할 수 있습니다. logback 등의 로깅 툴은 MDC(Mapped Diagnostic Context)를 제공하여 개발자가 직접 ThreadLocal을 사용하는 것보다 간편한 API를 사용해 멀티스레드 프로그램의 로깅 문제를 해결할 수 있습니다.

이 때 주목해야 할 중요한 가정은 하나의 요청을 하나의 스레드가 처리한다는 점입니다. 예를 들어 요청을 처리하면서 시간이 매우 오래 걸리는 작업을 처리하기 위해 스레드를 추가로 생성해서 병렬로 실행하거나 오래 기다려야 하는 IO 작업을 비동기로 실행할 스레드를 사용할 수 있습니다. 이런 경우 사용자는 스레드가 바뀔 때마다 MDC를 직접 수정해야 합니다. Armeria 또한 하나의 요청이 여러 스레드를 거쳐 처리될 수 있기 때문에 이를 염두에 두어야 합니다. 이 글에서는 MDC를 직접 사용할 때 겪을 수 있는 문제와 Armeria가 제공하는 도구를 사용해 이를 해결하는 과정을 담았습니다.

예제 시나리오 구현하기

하나의 요청을 여러 스레드가 처리하는 경우 MDC 사용 시 문제가 발생할 수 있으므로 이를 보여줄 수 있는 예제로 Armeria의 REST API 튜토리얼 코드를 사용합니다. 간단한 CRUD 애플리케이션인데 삭제 API를 구현할 때 @Blocking 어노테이션을 사용해 별도의 스레드를 생성해 처리를 맡깁니다. Armeria는 시간이 오래 걸리는 CPU-intensive 작업이나 지연시간이 긴 IO 작업 시 이벤트 루프를 블록하는 것을 막기 위해 별도의 스레드(Blocking task executor)에 작업을 위임할 수 있습니다.

받은 요청을 처리하기 전에 MDC에 추적용 ID를 설정하고 요청이 끝날 때 MDC를 비워줄 데코레이터를 만듭니다.

특별히 어려운 부분은 없고 serve 메소드 내부에서 MDC에 traceId를 넣어주고 다음 HttpService(REST 서비스)의 작업을 끝낸 뒤 MDC를 비워줍니다. MDC에 traceId가 들어간 후에 REST 서비스에서 로그를 남기면 traceId가 함께 출력되어 한꺼번에 여러 스레드가 실행되어도 로그를 모아 볼 수 있습니다. 해당 과정을 간단하게 도식화하면 다음과 같습니다.

문제 상황 (하나의 요청이 여러 스레드를 거치는 경우)

그럼 이제 서버를 실행해 어떻게 로그가 찍히는지 직접 확인해봅니다. 이 때 logback.xml을 다음과 같이 설정하여 어떤 스레드에서 실행되는지와 traceId를 함께 출력합니다.

먼저 블로그 컨텐츠 생성 API를 사용합니다. 해당 API를 처리하는 메소드는 @Blocking이 붙어있지 않기 때문에 하나의 스레드가 요청을 실행합니다.

로그를 보시면 5개의 로그가 모두 같은 스레드(armeria-common-worker-kqueue-3-2)에서 출력된 것을 확인할 수 있습니다. traceId는 MDC에 집어넣은 후부터 로그에 포함되고 MDC#clear()로 비워주면 다시 보이지 않는 것을 확인할 수 있습니다. 가장 중요한 3번째 로그를 보면 “createBlogPost” 메시지가 잘 찍혔으며 예상한대로 동일한 스레드, 동일한 traceId를 갖고 있습니다.

다음은 문제가 발생하는 블로그 컨텐츠 삭제 API입니다. @Blocking 메소드가 붙어있으므로 별도의 스레드에서 삭제 작업을 처리합니다.

세 번째 로그를 보면 다른 스레드(armeria-common-blocking-tasks-2-1)에서 로그가 찍혔고 이 때문에 데코레이터에서 설정해준 traceId를 갖고있지 않습니다. 따라서 Armeria 처럼 하나의 요청을 여러 스레드가 처리하는 경우 MDC만으로는 추적이 어렵다는 사실을 확인했습니다.

참고로 deleteBlogPost 메소드는 비동기로 다른 스레드에서 실행되기 때문에 아래와 같이 로그가 데코레이터의 로그보다 늦게 찍힐 수 있습니다. 즉, 순서를 보장하지 않습니다.

해결! RequestContext를 활용해라

Armeria는 하나의 요청이 여러 스레드를 넘나들면서 여러 메소드를 거쳐 처리될 때 공유하는 컨텍스트를 RequestContext에 저장합니다. (서버의 경우 ServiceRequestContext) 그리고 RequestContext는 고유 아이디를 갖고 있기 때문에 이 아이디를 로그에 함께 찍으면 스레드가 바뀌어도 추적할 수 있습니다.

먼저 데코레이터의 로깅 코드에 요청 ID를 함께 출력합니다.

그 다음 deleteBlogPost에서 ServiceRequestContext를 주입받도록 파라미터에 추가하고 요청 ID를 로그에 함께 출력합니다.

그럼 다음과 같이 로그에서 스레드가 바뀌었음에도 동일한 요청 ID가 찍히는 것을 확인할 수 있습니다.

하지만 이렇게 일일이 RequestContext 아이디를 포함해 모든 로그를 찍는 것은 너무 번거롭습니다. 다행히 Armeria에서 이를 대신해주는 RequestContextExportingAppender를 제공합니다. 사용하는 방법도 공식 문서에 있으니 참고하시면 되겠습니다.

문서에 써있는대로 armeria-logback 의존성을 추가한 뒤 logback.xml을 다음과 같이 설정해 요청 아이디를 로그에 함께 찍습니다. traceId는 더 이상 필요없지만 비교하기 위해 지우지 않았습니다.

데코레이터와 deleteBlogPost 메소드 모두 앞 챕터의 MDC 실습 예제 코드를 똑같이 사용하여 RequestContext의 요청 아이디와 traceId가 어떻게 다르게 동작하는지 확인합니다.

RequestContextExportingAppender를 사용했기 때문에 번거롭게 RequestContext에서 아이디를 추출할 필요도 없고 출력도 훨씬 보기 좋습니다. 요청 아이디는 데코레이터부터 REST 서비스까지 모두 동일하게 유지되는 것을 확인할 수 있습니다. MDC를 이용해 수동 설정한 traceId는 앞에서 봤듯이 deleteBlogPost를 실행할 때 그 값을 잃어버리는 것을 볼 수 있습니다.

RequestContext를 더 알고 싶다

지금까지 Armeria에서 MDC를 직접 사용하면 겪을 수 있는 문제와 RequestContextExportingAppender를 사용해 해결하는 과정까지 알아보았습니다. 결국 이런 편리한 로깅이 가능했던 이유는 스레드가 바뀔 때마다 RequestContext가 잘 전달되기 때문입니다. 사실 이 글도 RequestContext가 어떻게 스레드가 바뀔 때 전달되는지 공부하다가 부수적으로 만들어진 글입니다. 그 과정을 모두 이해하게되면 또 글로 써보려 합니다.

MDC를 이용한 로깅 외에도 Armeria는 하나의 요청이 여러 마이크로 서비스를 거칠 때 이를 추적하는데 도움을 주는 zipkin과의 통합도 지원합니다. 아마 다음 글은 이를 직접 실습해보고 정리하는 글일 될 것 같습니다. 😄 이 글을 읽으시는 분들도 기회가 된다면 Armeria 공식 문서를 직접 구현한 경험이나 현업에서 사용한 경험을 공유해주시면 큰 도움이 될 것입니다.