멀티스레드 분산 환경에서의 로깅(2)

---

서론

 

이전 포스팅과 이어 작성됩니다.

 

2023.05.21 - [Tech/Java&Spring] - 멀티스레드 분산 환경에서의 로깅(1)

멀티스레드 분산 환경에서의 로깅(1)

 

지난 포스팅에서 결론은 하나의 요청에서 파생된 로그인지 확인하기 어렵다는 결론이었습니다.

그래서, 이번 포스팅에서는 이를 해결할 수 있는 MDC Filter를 적용해봅니다.

---

MDC란

MDC: Mapped Diagnostic Context

MDC는 slf4j 패키지에 속해있는 클래스입니다. 

또한 ThreadLocal을 이용해 각 스레드에서만 유지되는 정보입니다.

 

MDC.java의 일부 코드를 살펴보겠습니다.

 

    public static void put(String key, String val) throws IllegalArgumentException {
        if (key == null) {
            throw new IllegalArgumentException("key parameter cannot be null");
        }
        if (mdcAdapter == null) {
            throw new IllegalStateException(MDC_APAPTER_CANNOT_BE_NULL_MESSAGE);
        }
        mdcAdapter.put(key, val);
    }

 

MDC.put 메서드를 호출 할 수 있도록 static으로 선언되어 있으며, 일반적인 Map 형태와 동일하게 key, value를 파라미터로 받고 있습니다.

여기 보이는 mdcAdapter는 MDCAdapter.java라는 인터페이스인데 구현체인 logback을 기준으로 설명해보겠습니다.

 

Logback 오픈소스 링크: https://github.com/qos-ch/logback/blob/master/logback-classic/src/main/java/ch/qos/logback/classic/util/LogbackMDCAdapter.java

 

public class LogbackMDCAdapter implements MDCAdapter  {

    final ThreadLocal<Map<String, String>> readWriteThreadLocalMap = new ThreadLocal<Map<String, String>>();
    final ThreadLocal<Map<String, String>> readOnlyThreadLocalMap = new ThreadLocal<Map<String, String>>();
    
    public void put(String key, String val) throws IllegalArgumentException {
        if (key == null) {
            throw new IllegalArgumentException("key cannot be null");
        }
        Map<String, String> current = readWriteThreadLocalMap.get();
        if (current == null) {
            current = new HashMap<String, String>();
            readWriteThreadLocalMap.set(current);
        }

        current.put(key, val);
        nullifyReadOnlyThreadLocalMap();
    }
    
    private void nullifyReadOnlyThreadLocalMap() {
        readOnlyThreadLocalMap.set(null);
    }
}

 

LogbackMDCadapter라는 구현체를 살펴보니 내부적으로 ThreadLocal을 사용하고 있는 것을 볼 수 있습니다.

 

읽기전용과 읽기쓰기용 ThreadLocal의 구분

위 코드를 다시 자세히 살펴 보시면 readOnlyThreadLocalMap과 readWriteThreadLocakMap이 구분되어 있습니다.

이 둘이 구분되어 있는 이유는 변수명 그대로 읽기 전용인지, 읽기와 쓰기 둘 다 가능한지에 대한 차이입니다.

다른 스레드와 경합을 벌이는 것도 아닌데 왜 한 스레드에서 읽기 전용을 구분해야하지? 라는 의구심이 있었습니다.

 

하지만 단순하게 생각해보면, 같은 스레드 내에선 언제든 값이 변경 가능하다는 점을 잊어선 안됩니다.

 

따라서 readOnly는 가장 최신 상태의 값을 유지하려 하며, null인 경우 readWrite의 값을 가져와 불변 객체로 생성하는 과정을 가집니다.

 

 

 

MDC Filter 적용

Github Repository

@Component
public class MdcFilter extends OncePerRequestFilter {

    public static final String MDC_KEY_TRACE_ID = "traceId";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        try {
            String traceId = UUID.randomUUID().toString();

            MDC.put(MDC_KEY_TRACE_ID, traceId);

            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(MDC_KEY_TRACE_ID);
        }
    }
}

ThreadLocal에 traceId라는 key 값으로 UUID를 넣어 각 요청(스레드) 별 로그를 구분할 수 있게 되었습니다.

사용된 Thread는 ThreadPool에 다시 돌아가기에 반드시 설정한 상태 값은 제거해주어야 합니다.

MDC는 ThreadLocal로 구현되어 있으므로 ThreadLocal과 동일하게 remove를 해주어 사용한 UUID를 제거해주고 있습니다.

 

결과

이번에도 K6를 통해 동일하게 테스트하였으며 약 5000줄의 로그가 적재되었습니다.

이전과는 다르게 스레드 이름에 의존하기 보다는 traceId로 설정한 UUID를 보며 추적할 수 있게 되었습니다.

 

2023-06-04 23:10:53 [http-nio-8080-exec-14] INFO  c.e.multithreadlogging.LoggingAOP - [1f62bc97-75d2-469c-87c7-9baba30f735f] timestamp: 2023-06-04 23:10:53.935
... 중략
2023-06-04 23:10:54 [http-nio-8080-exec-14] INFO  c.e.multithreadlogging.LoggingAOP - [1f62bc97-75d2-469c-87c7-9baba30f735f] result: BaseResponse(status=200, data=true, message=booking success)