Webflux with MDC

Spring Webflux 를 개발하다보면 비동기 어플리케이션의 모니터링의 어려움을 겪게된다.
이를 MDC 를 활용하여 해결할 수 있다.

 

1. MDC (Mapped Diagnostic Context) 란?

멀티스레딩 서버에서 여러 개의 스레드가 동시에 실행되면서 로그를 찍으면 로그를 구분할 수 없게 된다.
그래서 요청마다 ID(Correlation ID)를 부여하여 요청마다 로그를 모아서 볼 수 있다.
(Spring Cloud Slueth가 Trace Id 를 부여하는 것과 동일하다.)
요청을 처음 받았을때 Correlation ID를 생성하고, 이를 ThreadLocal에 저장했다가 로그를 쓸때 매번 이 ID를 ThreadLocal에서 꺼내서 같이 출력하면 된다.

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

---

 

2. with WebFlux

참고: 배달의민족 최전방 시스템! ‘가게노출 시스템’을 소개합니다. | 우아한형제들 기술블로그

문제는 Webflux에서는 한번의 요청에도 스레드 전환이 빈번하게 일어난다는 것이다.
대부분의 MDC 동작은 Thread 를 중심으로 작성된다.
전통적인 Thread Model 에서는 요청부터 응답이 같은 Thread 로 수행되기 때문에 MDC를 사용하기 쉬웠지만, Asynchronous NIO 기반의 Reactor 에서는 하나의 요청에서도 수십번 Thread 탈바꿈이 일어나게 된다.



따라서 , 스레드 전환이 한 번이라도 일어나면 새로운 스레드에게 MDC 메타 데이터를 전달하고
새로운 스레드에서 MDC를 하고, 기존 스레드에서 MDC를 삭제해야 한다.

2.1. Log 파일 적용

// traceId 가 본인이 정한 MDC 의 요청 ID 이다. (Custom 가능)

// Logback
Pattern : [%X{<Key>:-<Default>}]
Example (1) : [%X{traceId:-startup}] %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n
Example (2) : [%thread] %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n

// Log4J2
Pattern : [%equals{%X{<Key>}}{}{<Default>}]
Example : [%equals{%X{traceId}}{}{startup}] %d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n

2.2. MdcContextLifter.java

2.3. MdcContextLifterConfig.java

 

2.4. WebFilter.java

 

3. 게시글 상세보기 요청 로그

 

# 게시글 상세보기 요청
GET http://localhost:18088/boards/2

아래 로그는 게시글 상세보기 1회 요청을 했을 때 로그이다.

14:21:35.900 [boundedElastic-1] [traceId=83ba6a03-64e8-4773-beca-3006315a75e2] INFO  com.demo.api.service.BoardHandler: Thread test hello!
14:21:36.005 [reactor-http-nio-2] [traceId=83ba6a03-64e8-4773-beca-3006315a75e2] INFO  com.demo.api.filter.MdcLoggingFilter: GET http://localhost:18088/boards/2

boundedElastic-1 는 DB 쓰레드이며
reactor-http-nio-2 는 reactor nio 쓰레드 이다.

이는 비동기 어플리케이션이 Thread 명으로 사용자 요청 Flow 를 추적하기 힘든 어플리케이션임을 증명한다.
따라서 traceId=83ba6a03-64e8-4773-beca-3006315a75e2 라는 MDC 식별자를 통해 한 요청이 오면 ID 를 발급한후에 Thread Context 스위칭이 일어날때마다 MDC 메타데이터를 넘겨주는 방식으로 요청 로그를 관리할 수 있다.