아키텍쳐 /대용량 아키텍쳐

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

Terry Cho 2019. 3. 23. 22:28

로깅 시스템 #4 - Correlation id & MDC

조대협(http://bcho.tistory.com)

Correlation id

하나의 프로그램은 여러개의 메서드들로 조합이 된다. 하나의 요청을 처리하기 위해서는 여러개의 메서드들이 순차적으로 실행이 되는데, 멀티 쓰레드 프로그램에서 여러개의 쓰레드 동시에 각각의 요청을 처리할때, 각 메서드에 로그를 남기게 되면, 멀티 쓰레드 프로그램에서는 쓰레드들이 서로 컨택스트를 바꿔가며 실행이 되기 때문에, 로그 메시지가 섞이게 된다

아래 그림을 보자.


요청 A와 B가 호출되어 각각 다른 쓰레드에서 실행이 되었을때, 위의 그림과 같이 로그 메시지가 섞이게 된다. 이런 경우 요청 A에 대한 처리 내용을 확인하기 위해서 요청 A에 대한 로그만을 보고 싶을때 로그가 섞여 버려서 요청 A에 대한 로그만을 분리해내는 것이 어렵다.


이런 문제를 해결하기 위해서는 로그를 기록할때, 요청 마다 고유의 ID를 부여해서 로그를 기록하게 되면, 그 ID를 이용해서 각 요청마다의 로그를 묶어서 볼 수 있다.


위의 그림을 보면 요청 A에 대해서는 “1”이라는 ID를 지정하고, 두번째로 들어온 요청 B에 대해서는 “A”라는 ID를 지정하면, 이 ID로 각 요청에 대한 로그들을 묶어서 조회할 수 있다. 이를 Correlation ID라고 한다.

ThreadLocal

그러면 이 Correlation ID를 어떻게 구현해야 할까?

요청을 받은 메서드에서 Correlation ID를 생성한 후, 다른 메서드를 호출할때 마다 이 ID를 인자로 넘기는 방법이 있지만, 이 방법은 현실성이 떨어진다. ID를 넘기기 위해서 모든 메서드에 공통적으로 ID 필드를 가져야 하기 때문이다.

이런 문제는 자바에서는 ThreadLocal이라는 변수를 통해서 해결할 수 있다.

ThreadLocal을 쓰레드의 로컬 컨텍스트 변수로 Thread 가 존재하는 한 계속해서 남아 있는 변수이다.

무슨 이야기인가 하면, 작업 요청이 들어왔을때, 하나의 쓰레드가 생성이 되고 작업이 끝나면 쓰레드가 없어진다고 하면, 쓰레드가 살아있을 동안에, 계속 유지되는 변수이다. 즉 쓰레드가 생성되어 있는 동안에, 쓰레드 안에서 계속 참고해서 쓸수 있는 쓰레드 범위의 글로벌 변수라고 생각하면 된다.

그래서 요청을 처음 받았을때 Correlation ID를 생성하고, 이를 ThreadLocal에 저장했다가 로그를 쓸때 매번 이 ID를 ThreadLocal에서 꺼내서 같이 출력하면 된다. 이 개념을 그림으로 표현해보면 다음과 같다.


ThreadLocal의 ID 변수에 Correlation ID를 저장해놓고, 각 메서드에서 이 값을 불러서 로그 출력시 함께 출력하는 방법이다.

MDC

그러나 이걸 일일이 구현하기에는 불편할 수 있기 때문에, slf4j,logback,log4j2등의 자바 로그 프레임워크에서는 이런 기능을 MDC(Mapped Diagnostic Context)로 제공한다.

단순하게 CorrelationID 뿐만 아니라 map 형식으로 여러 메타 데이타를 넣을 수 있다. Correlation ID는 여러 요청을  묶을 수 는 있지만 다양한 요청에 대한 컨텍스트는 알 수 없다. 실행되는 요청이 어떤 사용자로 부터 들어온것인지, 또는 상품 주문시 상품 주문 ID를 넣는다던지, 요청에 대한 다양한 컨텍스트 정보를 MDC에 저장하고 로그 출력시 함께 출력하면 더 의미 있는 로그를 출력할 수 있다.


MDC를 사용한 코드를 작성해보자

이 예제에서는 slf4j와 logback을 사용한다. 아래처럼 logback과 json 관련 의존성을 pom.xml 에 정의한다.


<dependencies>

<dependency>

<groupId>ch.qos.logback</groupId>

<artifactId>logback-classic</artifactId>

<version>1.1.7</version>

</dependency>


<dependency>

<groupId>ch.qos.logback.contrib</groupId>

<artifactId>logback-json-classic</artifactId>

<version>0.1.5</version>

</dependency>


<dependency>

<groupId>ch.qos.logback.contrib</groupId>

<artifactId>logback-jackson</artifactId>

<version>0.1.5</version>

</dependency>


<dependency>

<groupId>com.fasterxml.jackson.core</groupId>

<artifactId>jackson-databind</artifactId>

<version>2.9.3</version>

</dependency>

</dependencies>



그리고 로그를 json 포맷으로 출력하기 위해서 아래와 같이 logback.xml 을 작성하여, main/resources/logback.xml 로 저장한다.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

   <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">

       <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">

           <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">

               <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSX</timestampFormat>

               <timestampFormatTimezoneId>Etc/UTC</timestampFormatTimezoneId>


               <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">

                   <prettyPrint>true</prettyPrint>

               </jsonFormatter>

           </layout>

       </encoder>

   </appender>


   <root level="debug">

       <appender-ref ref="stdout"/>

   </root>

</configuration>



다음 아래와 같이 간단하게 MDC를 테스트 하는 코드를 작성한다.

package com.terry.logging.logbackMDC;


import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

import org.slf4j.MDC;



public class App

{

   private static Logger log = LoggerFactory.getLogger(App.class);

   public static void main( String[] args )

   {

    log.info("Hello logback");

   

    MDC.put("userid", "terrycho");

    MDC.put("event", "orderProduct");

    MDC.put("transactionId", "a123");

    log.info("mdc test");

   

    MDC.clear();

    log.info("after mdc.clear");

   }

}


MDC를 사용하는 방법은 MDC에 값을 넣을때는 mdc.put(key,value)를 이용하여, 값을 넣고 지울때는  mdc.remove(key)를 이용해서 특정 키를 삭제한다. 전체를 지울때는 mdc.clear()를 사용한다. mdc에 저장된 내용은 logger를 이용해서 로그를 출력할때 마다 mdc 라는 element로 자동으로 함께 출력된다.

위의 예제를 보면 log.info(“hello logback”)으로 로그를 출력하였고 그 다음 mdc에 userid,event,transactionid 라는 키들로 값을 채운 다음에 log.info(“mdc test”)라는 로그를 출력하였다. 그리고 마지막에는 mdc를 모두 지운 후에 “after mdc clear”라는 로그를 출력하는 코드이다. 결과는 다음과 같다.


{

 "timestamp" : "2019-03-23T05:42:19.102Z",

 "level" : "INFO",

 "thread" : "main",

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "Hello logback",

 "context" : "default"

}{

 "timestamp" : "2019-03-23T05:42:19.118Z",

 "level" : "INFO",

 "thread" : "main",

 "mdc" : {

   "event" : "orderProduct",

   "userid" : "terrycho",

   "transactionId" : "a123"

 },

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "mdc test",

 "context" : "default"

}{

 "timestamp" : "2019-03-23T05:42:19.119Z",

 "level" : "INFO",

 "thread" : "main",

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "after mdc.clear",

 "context" : "default"

}


첫번째 로그는 “Hello logback”이라는 메시지가 출력된 후에, 두번째 로그는 mdc 가 세팅되어 있기 때문에, mdc라는 element가 출력되는데, 그 안에 mdc에 저장한 event,userid,transactionid  값이 함께 출력되는 것을 볼 수 있다. 그리고 마지막에는 mdc를 clear 한후에, 로그를 출력하였기 때문에, 메시지만 출력이 되고 mdc 라는 element없이 출력된것을 확인할 수 있다.


slf4j+logback 을 사용할 경우에는 앞의 글에서 설명하였듯이 json으로 로그 출력시 message 문자열 하나면 json element로 출력할 수 있었다. 그래서 custom layout 등 다른 대체 기법을 사용하였는데, mdc를 사용하여 컨텍스트 정보를 넘기게 되면, slf4j와 logback의 제약 사항을 넘어서 json으로 여러 element를 로깅 할 수 있다.