spring boot logback MDC는 어떤 식으로 동작하는지 간단하게 분석해 봅시다.

 logback의 MDC에 대해서 문서를 보면서 공부하고 있습니다. 내부적으로 ThreadLocal을 이용을 한다는 것을 질문 답변 글에서 확인하였고, 그것 때문에 이 부분에 대해서도 공부를 하게 되었어요. 저는, 최근에 토이 프로젝트에서 요청을 날린 client의 ip를 로그에 추가하도록 바꾸었는데요. 이 과정에서 MDC를 이용하게 되었어요.

 

 제 logback은 1.2.9 버전을 쓰고 있습니다.

 

 

---

 logback-spring.xml에서 encoder의 pattern을 %X{AAA} - %msg%n 이렇게 설정을 하였습니다. 여기서 제가 궁금했던 것은 %X라는 친구가 어떤 식으로 내부적으로 동작을 해서, MDC에 있는 것을 읽어오느냐는 것이였습니다. 이 %X는 MDC에서 AAA를 key값으로 가지는 value를 얻어오는 것입니다.

 

 

 Controller는 간단합니다. org.slf4j.MDC를 import 하였는데요. 여기서 MDC는 org.slf4j.MDC를 의미합니다.

 

 

 GET /test api를 호출해 보았습니다. 그랬을 때, 어떤 일이 일어나는지 천천히 보겠습니다.

 

 

 Frames를 보면 PatternLayoutBase가 있는데요. writeLoopOnConverters를 보겠습니다. 보면 event가 [INFO] /test라고 되어 있습니다. 이 때 for loop에 있는 c를 보도록 하겠습니다.

 

 

 그러면, next로 계속 뭔가가 이어져 있는 것을 볼 수 있는데요. List 비슷한 형태로 관리하고 있는 무언가임을 알 수 있어요. 그리고 조금 더 눈치를 채셨다면, token별로 끊어서 저장했음을 알 수 있는데요. 기본적인 전처리 작업을 미리 해 두었음을 알 수 있어요. 특정한 플래그에 따라 어떤 Convertor를 사용할지도 나오는데요. MDCConvertor, MessageConvertor, LineSeparatorConvertor 등을 씀을 알 수 있어요.

 

 %X{AAA} 이 부분은 MDCConvertor로 변환할 거라는 것을 알 수 있습니다. 계속 타고 들어가 보겠습니다.

 

 

 MDCConverter의 convert 부분을 보면 mdcPropertyMap을 얻어오는 것을 볼 수 있어요.

 

 

 여기서 봐야 할 부분은 SynchronizedMap@5995입니다. 키로 넘어온 것이 AAA였고, propertyMap에 AAA를 키 값으로 가지는 것의 value가 bbb였기 때문에 bbb를 리턴하게 됩니다. 그리고 이 리턴값은 버퍼에 들어가서 출력 결과에 반영되게 됩니다.

 

---

 

 이제 이 부분을 보겠습니다. MDC의 remove인데요. key "AAA"를 제거한다고 합니다. 이러면 어떻게 될까요?

 

 

 mdcAdapter의 remove가 호출됩니다. mdcAdapter의 remove를 보겠습니다.

 

 

 보면, oldMap을 불러오는 부분이 있습니다. adapter의 copyOnThreadLocal의 get 메서드를 호출하는데요.

 

 

 oldMap을 보면 SynchronizedMap@5995임을 알 수 있어요. logback에서 logging을 할 때 썼던 propertyMap과 동일한 객체를 보고 있음을 알 수 있어요. 그리고 copyOnThreadLocal은 ThreadLocal임을 알 수 있는데요.

 

 

 이 관계를 그림으로 그려보면 위와 같습니다. 이제 남는 의문이 있습니다. convert에서 어떻게 저 친구를 불러왔을까요?

 

 

---

 호출 스택을 계속 따라 내려가다 보니, LoggingEvent라는 친구를 발견하게 되었습니다.

 

 

 getMDCPropertyMap에 함수 브레이크 포인트를 걸고 GET /test api를 실행하였습니다.

 

 

 그랬더니 이 부분에서 걸렸는데요. prepareForDeferredProcessing 메소드를 호출하게 됩니다. encode를 하기 전입니다.

 

 

 이 getMDCPropertyMap은 MDC와 관련된 map을 호출하는데요.

 

 

 this.copyOnThreadLocal.get()이 있네요. 그런데 이 copyOnThreadLocal은 어디선가 본 친구인 거 같은데요.

 

 

 제가 노란색으로 칠한 것을 의미합니다. 결국 logback에서 %X{AAA}가 있다면 쓰레드 지역 변수인 map을 불러온 다음에, 키 값 "AAA"에 매칭되는 value 값을 찾아서 대치시키게 됩니다.