[Logging] MDC

MDC?

• Mapped Diagnostic Context의 약자로 주로 여러 스레드나 사용자 요청 간에 로깅 메시지에 추가적인 정보를 제공하기 위해 사용된다

MDC를 사용하는 이유

import org.apache.log4j.Logger;
import com.baeldung.mdc.TransferService;

public abstract class TransferService {

    public boolean transfer(long amount) {
        // connects to the remote service to actually transfer money
    }

    abstract protected void beforeTransfer(long amount);

    abstract protected void afterTransfer(long amount, boolean outcome);
}

public class Log4JTransferService extends TransferService {
    private Logger logger = Logger.getLogger(Log4JTransferService.class);

    @Override
    protected void beforeTransfer(long amount) {
        logger.info("Preparing to transfer " + amount + "$.");
    }

    @Override
    protected void afterTransfer(long amount, boolean outcome) {
        logger.info(
          "Has transfer of " + amount + "$ completed successfully ? " + outcome + ".");
    }
}

• 송금 전 후 로그를 찍는 서비스
• 로그가 amount만 로그가 찍혀있고, 누가 송금한 지 알 수 없다.

public class TransferDemo {

    public static void main(String[] args) {
        ExecutorService executor = Executors.newFixedThreadPool(3);
        TransactionFactory transactionFactory = new TransactionFactory();
        for (int i = 0; i < 10; i++) {
            Transfer tx = transactionFactory.newInstance();
            Runnable task = new Log4JRunnable(tx);            
            executor.submit(task);
        }
        executor.shutdown();
    }
}

public class Log4JRunnable implements Runnable {
    private Transfer tx;
    
    public Log4JRunnable(Transfer tx) {
        this.tx = tx;
    }
    
    public void run() {
        log4jBusinessService.transfer(tx.getAmount());
    }
}

• ExecutorService를 통해 여러 명의 사용자가 송금을 한다고 가정해보자.
• 테스트를 해보면 아래와 같은 결과가 나온다.

...
519  [pool-1-thread-3]  INFO Log4JBusinessService 
  - Preparing to transfer 1393$.
911  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1065$ completed successfully ? true.
911  [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1189$.
989  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Has transfer of 1350$ completed successfully ? true.
989  [pool-1-thread-1]  INFO Log4JBusinessService 
  - Preparing to transfer 1178$.
1245 [pool-1-thread-3]  INFO Log4JBusinessService 
  - Has transfer of 1393$ completed successfully ? true.
1246 [pool-1-thread-3]  INFO Log4JBusinessService 
  - Preparing to transfer 1133$.
1507 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Has transfer of 1189$ completed successfully ? true.
1508 [pool-1-thread-2]  INFO Log4JBusinessService 
  - Preparing to transfer 1907$.
1639 [pool-1-thread-1]  INFO Log4JBusinessService 
  - Has transfer of 1178$ completed successfully ? true.
1640 [pool-1-thread-1]  INFO Log4JBusinessService 
  - Preparing to transfer 674$.
...

• 각각의 스레드가 순서를 보장하지 않고 로그를 콘솔에 찍는 것을 볼 수 있다.
• 또한 같은 스레드에서 실행 됐을 경우 동일한 금액을 보냈을 시, 이를 판별할 수 있는 고유 값이 존재하지 않는다.

이러한 상황을 MDC를 사용해 해결할 수 있다.

MDC를 이용한 구현

• MDC 구조는 ThreadLocal 변수와 동일한 방식으로 실행 스레드에 내부적으로 실행되고 있다.
• 구현 로직은 아래와 같다.
  • Appender 제공할 정보로 MDC를 채워서 준다.
  • 그런 다음 메시지를 기록
  • 완료 뒤 MDC를 비운다.

import org.slf4j.MDC;

public class Slf4jRunnable implements Runnable {
    private final Transaction tx;
    
    public Slf4jRunnable(Transaction tx) {
        this.tx = tx;
    }
    
    public void run() {
        MDC.put("transaction.id", tx.getTransactionId());
        MDC.put("transaction.owner", tx.getOwner());
        new Slf4TransferService().transfer(tx.getAmount());
        MDC.clear();
    }
}

• MDC.put()은 key value를 추가하는데 사용됨
• MDC.clear()는 MDC 로그를 비우는데 사용

<configuration>
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%-4r [%t] %5p %c{1} - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n</pattern>
	</encoder>
    </appender>
    <root level="TRACE">
        <appender-ref ref="stdout" />
    </root>
</configuration>

• 그 다음 MDC에 정의한 key를 Appender에 제공한다.

1020 [pool-1-thread-3]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1869$ completed successfully ? true. - tx.id=3 tx.owner=John
1021 [pool-1-thread-3]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 1303$. - tx.id=6 tx.owner=Samantha
1221 [pool-1-thread-1]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1498$ completed successfully ? true. - tx.id=4 tx.owner=Marc
1221 [pool-1-thread-1]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 1528$. - tx.id=7 tx.owner=Samantha
1492 [pool-1-thread-2]  INFO c.b.m.s.Slf4jBusinessService 
  - Has transfer of 1110$ completed successfully ? true. - tx.id=5 tx.owner=Samantha
1493 [pool-1-thread-2]  INFO c.b.m.s.Slf4jBusinessService 
  - Preparing to transfer 644$. - tx.id=8 tx.owner=John

• 그 이후 로직을 다시 실행하면 위와 같이 예쁜 순서의 로그를 볼 수 있다.

MDC와 스레드 로컬

• MDC 구현은 일반적으로 스레드 로컬을 사용하여 컨텍스트 정보를 저장.
• thread-safey 조건을 충족하는 쉬운 방법 중 하나
• 하지만 스레드 풀을 사용할 때 MDC의 값을 지우지 않고 스레드를 반환하면 다음에 스레드를 사용하는 서버에 이전 로그가 남아있는 현상이 발생할 수 있다. 이는 잘못된 로그를 서버에 기록할 수 있으므로 실행이 끝날 때 마다MDC.clear()로 MDC의 값을 비워줘야 한다.
• 필터나 인터셉터에서 destroy 시 위의 로직을 추가해주면 된다.

실제로 회사에서 키바나에 url이 이상하게 찍혔던 적이 있는데, 다음 글에는 이를 해결한 방법을 간단하게 작성해보겠다.

Reference: https://www.baeldung.com/mdc-in-log4j-2-logback