로그를 분류해야하는 경우
스프링에서 로그를 남길 때 대부분 Logback을 사용한다.
보통 한 파일에 모든 로그를 남기기보다는 기능, 모듈별로 로그를 남기거나 어떠한 기준(로그 레벨등...)에 의해 로그를 여러 파일 혹은 여러 디렉토리에 남긴다.
그렇게 구현하려면 logback 설정 파일(logback-spring.xml 같은 파일)에서 property로 여러 로그 경로를 등록해놓고 logger의 패키지를 나눠서 지정하는 것이 일반적인 방법일 것이다.
그러나 위의 방법은 어느정도 패키지 분류가 되어있는 상태여야하고 분류할 기준의 개수가 제한적이어야 한다.
어느정도는 Logback의 filter를 이용한 방법으로 쉽게 처리할 수도 있겠지만, 여전히 같은 패키지, 같은 클래스의 로그에 대해서는 분류하기 어려울 것이다.
또한 어떠한 Request를 스프링에서 처리할 때 하나의 쓰레드에서 모든 것을 처리하지 않고 여러 Service들을 왔다갔다하고 심지어 멀티 쓰레드로 동시에 작업이 진행되기도 한다.
그러한 경우 로그를 그냥 쌓아버리면 로그가 섞이게 된다.
물론 패턴에 %logger로 어떤 패키지의 클래스에서 로그를 적었는지 알 수 있지만 예를 들어 어떤 상품을 주문하던 중이었는지, 어떤 유저가 작업중이었는지 등의 정보를 분류하기 위해서는 좀 더 특별한 기능이 필요하다.
이럴 때 MDC라는 것으로 처리할 수 있다.
MDC
MDC는 Mapped Diagnostic Context다. 해석하기는 어렵고(?) 그냥 Logback에서 여러 메타 정보를 넣을 수 있고 공유되는 Map이라고 생각하면 쉽다.
이 Map(MDC)에 분류할 경로를 넣는다든지 주문중이던 상품코드나, 유저 이름등을 넣는다든지 해서 더 명확하게 로그를 분류할 수 있는 기준을 만들 수 있다.
사용법을 통해 간단하게 알아본다.
MDC 사용법
MDC를 사용하는 방법은 되게 간단하다! 그냥 Map이기 때문에 필요할 때 값을 넣어주고 필요하지 않으면 빼면 된다.
1) logback-spring.xml 에서 MDC 사용하기
<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="true" scan="true" scanPeriod="10 seconds">
<!-- :%-3relative -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<Pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}][%thread] %-5level %logger{35} - %msg%n</Pattern>
</layout>
</appender>
<appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
<discriminator>
<key>userid</key>
<defaultValue>etc</defaultValue>
</discriminator>
<sift>
<appender name="ROLLING_ROOT" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./Log/${userid}/logback.log</file>
<encoder>
<pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}][%thread] %-5level %logger{35} %mdc - %msg%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>./Log/${userid}/logback.%d{yyyy-MM-dd_HH}.%i.log.gz</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<!-- or whenever the file size reaches 100MB -->
<maxFileSize>50MB</maxFileSize>
<!-- kb, mb, gb -->
</timeBasedFileNamingAndTriggeringPolicy>
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
</sift>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT" />
<appender-ref ref="SIFT" />
</root>
</configuration>"SIFT"라는 이름으로 만든 SiftingAppender를 잘 살펴보도록 한다.
미리 참고로 말하면 꼭 SiftingAppender를 사용해야만 MDC를 사용할 수 있는 것은 아니다.
예제에서는 로그 경로를 동적으로 변경하기 위해서 저렇게 만들었다.
단순히 MDC를 사용하고자 하면 에는 %mdc 또는 %X{key} 이런식으로 사용하면 된다.
에 key와 defaultValue를 설정해서 MDC에 해당 key가 없으면 default로 사용할 값을 지정할 수 있다.
결국 RollingFileAppender에서는 ${userid}라는 것으로 경로를 지정한 것을 볼 수 있다.
이렇게 변경될 키 값(key)을 지정만 해두고 실제로 로그를 남길 때는 로그를 남기기 전에 아래의 코드처럼 MDC에 key, value를 입력해주기만 하면 된다.
2) MDC에 key, value 입력하기
package com.tistory.jeongpro.controller;
import java.util.Map;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import javax.annotation.PostConstruct;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.RestController;
import com.tistory.jeongpro.service.HelloService;
@RestController
public class TestController {
private static final Logger logger = LoggerFactory.getLogger(TestController.class);
private ExecutorService executorService = Executors.newFixedThreadPool(4);
@Autowired
private HelloService helloService;
@PostConstruct
private void init() {
//mdc 미적용
logger.info("hello world!!");
//mdc적용
MDC.put("userid", "hello");
logger.info("mdc parent");
//runnable
Thread childThread = new Thread(()->{
logger.info("mdc child");//mdc에 userid가 있으면 상속 받은것
});
childThread.run();
//executor
executorService.execute(()->{
logger.info("mdc executor");//mdc에 userid가 없으면 상속받지 못한 것
});
MDC.clear();
//괜히 MDC 변경
MDC.put("userid", "world");
Map<String, String> parentMDC = MDC.getCopyOfContextMap();//mdc를 참조하는 객체 생성
executorService.execute(()->{
MDC.setContextMap(parentMDC);
logger.info("wow mdc executor");
});
//service호출
helloService.hello();//service 안에서 로그찍음.
MDC.clear();
}
}다른 예시도 있어서 현란해 보이지만, 사실상 원하는 로그를 적기 전에 MDC에 값을 넣어놓기만 하면 된다. (MDC.put(key, value))
위의 예시에서는 MDC에 대한 값으로 "hello", "world" 라는 고정적인 값을 넣었는데, 필요하다면 product.getId() 같은 메타 정보를 MDC에 값으로 넣으면 된다.
사용법은 이것으로 끝이고,
로그 결과를 보기 전에, 왜 위에서 저렇게 예제코드를 짰는지 주의사항을 알고 넘어가도록 하자.
하나의 쓰레드에서만 사용된다면 위의 사용법대로 MDC에 값을 한 번만 넣고 쭉 로그를 작성하기만 하면 같은 분류로 로그가 작성된다.
그런데 멀티로 돌아갈 때는 어떨까?
평범하게 Runnable을 이용한 Thread 클래스를 통해서 생성된 쓰레드에서 로그를 작성하면 자동적으로 MDC까지 상속되어 부모에서 정의한 MDC를 사용할 수 있게 된다.
그런데 ThreadPool을 사용한 쓰레드에서는 MDC가 상속되지 않는다.
따라서 위의 예제처럼 MDC.getCopyOfContextMap();을 통해서 해당 객체의 레퍼런스를 갖고 그 레퍼런스를 쓰레드풀에서 참조할 수 있게 해주면 문제를 해결할 수 있다.
그렇다면 위의 예제처럼 controller에서 service를 호출할 때는 어떨까?
이 역시도 같은 쓰레드에서 처리하므로 MDC가 유지되는 모습을 확인할 수 있다.
이 점을 유의하며 아래 결과를 확인해보자.
→ ./Log/etc/logback.log파일 내의 일부 (기타로그도 다 여기에 찍혔기 때문에 일부다.)
[2019-10-02 21:24:08.523][restartedMain] INFO c.t.j.controller.TestController - hello world!!
[2019-10-02 21:24:08.535][pool-2-thread-1] INFO c.t.j.controller.TestController - mdc executor→ ./Log/hello/logback.log파일
[2019-10-02 21:24:08.524][restartedMain] INFO c.t.j.controller.TestController - mdc parent
[2019-10-02 21:24:08.534][restartedMain] INFO c.t.j.controller.TestController - mdc child→ ./Log/world/logback.log파일
[2019-10-02 21:24:08.535][restartedMain] INFO c.t.j.service.HelloServiceImpl - HelloServiceImpl hello!
[2019-10-02 21:24:08.536][pool-2-thread-2] INFO c.t.j.controller.TestController - wow mdc executor끝으로 생각해볼 문제가 조금 있다.
하나의 스프링 애플리케이션에서는 이렇게 처리하면 되지만, 요새 추세대로 스프링 클라우드를 적용한다면 어떨까?
A 스프링 애플리케이션에서 B스프링 애플리케이션을 호출할 때는 어떻게 MDC를 공유할 수 있을까?
API를 호출할 때 넘겨주는 Request에 정보를 담거나 HTTP Header에 담는 방법등이 있겠다만 나이스한 방법은 아닌 것 같다.
이에 대한 정보는 아래 참고 사이트에서 친절하게 설명해주시니 참고바라고 포스트 목적인 MDC를 간단히 알아보는 목적으로는 여기까지가 맞는 것 같다.
참고 사이트
