로깅 시스템
하나의 어플리케이션은 여러개의 메서드들의 합으로 이루어져 있습니다. 하나의 요청을 처리하기 위해서는 여러개의 메서드들이 순차적으로 실행됩니다. 그리고 멀티 쓰레드 프로그램에서 여러개의 쓰레드를 동시에 각각의 요청을 처리할 때 각 메서드에 로그를 남기게 되는 상황을 가정하겠습니다. 이 때 멀티쓰레드 프로그램에선 쓰레드들이 서로 Context를 바꿔가며 실행되기 때문에 로그 메세지가 섞이게 됩니다.
Correlation id
위의 사진처럼 요청 A와 B가 호출되어 각각 다른 쓰레드에서 실행되었을 때 위의 그림과 같이 로그 메세지가 섞이게 됩니다. 그리고 이 결과로 요청 1 혹은 요청 2에 대한 로그만을 분리하는 것은 어려워집니다.
이런 문제를 해결하기 위해 로그를 기록할 때 요청마다 고유의 ID를 부여해서 로그를 기록하게 되면 그 ID를 이용해서 각 요청마다의 로그를 ID로 묶을 수 있습니다.
아래의 그림에서 요청 1에 대해서는 ID를 1로, 요청 2에 대해서는 ID를 A로 지정하였고, 이 ID로 각 요청에 대한 로그들을 묶어서 조회할 수 있습니다.
이를 Correlation ID라고 합니다.
ThreadLocal
Correlation ID를 구현하는데 있어 요청을 받은 메서드에서 Correlation ID를 생성한 후, 다른 메서드를 호출할 때마다 이 ID를 인자로 보내는 방법이 가장 쉬워보입니다. 하지만 ID를 넘기기 위해서 모든 메서드에 공통적으로 ID 필드를 가져야 하기 때문에 현실적으로 어려울 수 있습니다.
이 문제를 JAVA에서는 ThreadLocal이라는 변수를 통해 해결합니다.
ThreadLocal은 쓰레드의 로컬 Context로, Thread가 계속 존재하는 한 계속 남아있는 변수입니다. 조금 더 자세히 말하자면 요청이 들어왔을 때 하나의 쓰레드가 생성되고 작업이 끝나면 쓰레드가 없어지는데, 쓰레드가 있는 동안 계속 유지되는 변수입니다.
그래서 요청을 처음 받았을 때 Correlation ID를 생성하고 이를 ThreadLocal에 저장했다가 로그를 찍을 때 매번 이 ID를 ThreadLocal에 꺼내서 같이 출력하면 됩니다.
MDC
위의 예시도 좋지만, Spring에서는 slf4j, logback, log4j등의 자바 로그 프레임워크에서 해당 기능을 MDC(Mapped Diagnostic Context)로 제공합니다.
단훈히 Correction ID 뿐만 아니라, map형식으로 여러 메타 데이터를 넣을 수 있습니다. 실행되는 요청이 어떤 사용자로부터 들어온 것인지, 쇼핑몰일 경우 상품 주문 ID 등 요청에 대한 컨텍스트 정보를 MDC에 저장할 수 있습니다.
아래의 예시는 slf4j와 logback을 사용합니다. 아래 코드로 logback과 json 관련 의존성을 build.gradle 에 정의합니다.
gradle
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-web'
}그리고 로그를 json 포맷으로 출력하기 위해서 아래와 같이 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("logback test");
MDC.put("userid", "David_Kim");
MDC.put("event", "orderProduct");
MDC.put("transactionId", "a123");
log.info("mdc test");
MDC.clear();
log.info("mdc cleared");
}
}MDC에 값을 넣을 때 MDC.put(key, value)를 이용하며, 값을 넣고 지울때는 MDC.remove(key)를 이용해 특정 키를 삭제합니다. 전체를 지울 때는 MDC.clear()를 사용합니다. MDC에 저장된 내용은 logger을 이용해서 log를 출력할 때 마다 MDC라는 element로 자동으로 함께 출력됩니다.
출력된 코드는 아래와 같습니다.
{
"timestamp" : "2022-08-02T17:22:19.118Z",
"level" : "INFO",
"thread" : "main",
"logger" : "dev.be.logging.logbackMDC.App",
"message" : "logback test",
"context" : "default"
}{
"timestamp" : "2022-08-02T17:22:19.118Z",
"level" : "INFO",
"thread" : "main",
"mdc" : {
"event" : "orderProduct",
"userid" : "David_Kim",
"transactionId" : "a123"
},
"logger" : "dev.be.logging.logbackMDC.App",
"message" : "mdc test",
"context" : "default"
}{
"timestamp" : "2022-08-02T17:22:19.118Z",
"level" : "INFO",
"thread" : "main",
"logger" : "dev.be.logging.logbackMDC.App",
"message" : "mdc cleared",
"context" : "default"
}첫 번째 로그에선 "logback test"라는 메세지가 출력된 후에, 두번째 로그에선 MDC가 설정되어있기 때문에 MDC element가 출력되는데, 이 때 같이 저장한 userid, event, transactionId값이 같이 출력되는 것을 확인할 수 있습니다. 그리고 마지막에는 MDC를 clear한 후에 로그를 출력했기 때문에, 메세지만 출력되고 MDC라는 elemen없이 출력된 것을 확인할 수 있습니다.
