TIL 2024-01-29 로그 MDC

 

 

@Around("@annotation(piglin.swapswap.global.annotation.SwapLog)")
    public Object swapLog(ProceedingJoinPoint joinPoint) throws Throwable {

        HttpServletRequest req = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();

        log.info("start transaction");
        log.info("\nMethod - {} | Method Argument - {}\nIP - {} | Browser - {}\n▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ Cookie ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼\n{} \n▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲",joinPoint.getSignature().getName(), joinPoint.getArgs(), getRemoteAddr(req), getBrowser(req),
                getCookie(req));

        Object result = null;
        try {
            result = joinPoint.proceed();
            log.info("success transaction");
        } catch (Throwable e) {
            log.error("failed transaction", e);
        }
        return result;

    }

 

어노테이션을 부착하여 쉽게 붙였다 뗐다 하면서 요청자를 파악할 수 있는 로깅 AOP 를 만들었다.

 

트랜잭션이 성공했는지 안 했는지를 보기 위해 Start Transaction을 넣어주고 Transaction이 끝났다면 끝났다고 말해주게 해주려고 했는데 계속 위화감이 들었다.

 

그래서 Order를 넣어주고 트랜잭션 전 AOP랑 트랜잭션 후 AOP로 계속 비교를 해봤는데 끝없이 드는 위화감...

 

왜냐하면 이건 트랜잭션이 시작했다는 log가 아니다. 말만 트랜잭션 start이고 사실은 메서드 Start 인 것

 

ㅋㅋㅋ 그러니까 위화감이 들지!

 

그래서 여러곳 자문해보니 MDC라는 것을 알게됐다.

 

 

MDC?

mdc(Mapped Diagnostic Context)는 로그 추적을 위해 만들어진 기능이다.

mdc는 멀티 쓰레드 환경에서 빛을 발하는데, 멀티 쓰레드 환경에서는 쓰레드 넘버를 로깅해줘야 같은 쓰레드에서 하는 행위인지 구분이 간다. 하지만 쓰레드가 비동기 메서드를 사용해서 달라지거나 하면 문제가 생기겠지?

 

분산 서버에서는 서버 -> 서버 통신이 발생하기 때문에 쓰레드가 바뀌어 로그 추적이 힘들 때 해당 행위에 대해 공통 ID(traceId, requestId) 를 부여해주는 오픈소스가 있다.

 

대표적인 것들은

zipkin, spring cloud sleuth 가 있는데 음!! 아직 이거 까지 알려면 멀었다. 스텝 바이 스텝~~

 

 

구현

요청을 받는 제일 앞단에서 처리를 해주는 것이 좋지만 (필터) 지금 내 서비스는 중요 로직에 어노테이션 aop 를 붙여서 사용 할 것이 때문에 그 부분에서 traceId를 붙여 줄 것이다.

 

spring-boot-starter-web 에 기본적으로 들어있음

spring-boot-starter-web 의존성을 추가해주면 slf4j 가 들어있는데 거기에 MDC가 이미 들어가 있다.spring boot 칭찬해~~

 

implementation 'org.springframework.boot:spring-boot-starter-web'

 

이거 넣어주면 됨~~

 

logback.xml 에서 traceId 보이게 설정하면 됨!!

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
  <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%clr(%d{[yyyy-MM-dd HH:mm:ss]}){yellow} [%35thread] [traceId=%X{traceId}] %clr(%-5level) %50logger{36} - %clr(%msg){blue}%n</pattern>
    </encoder>
  </appender>

  <appender name="LOGFILE" class="ch.qos.logback.core.FileAppender">
    <file>./log/swapswap.log</file>
    <encoder>
      <pattern>%d{[yyyy-MM-dd HH:mm:ss]} [%35thread] [traceId=%X{traceId}] %-5level %50logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="info">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="LOGFILE"/>
  </root>
</configuration>

 

[traceId=%X{traceId}] 이걸 appender - pattern 에 끼워주면 된다.

[key=value] 형식인데 그렇다는 건!! traceId 말고 다른 이름으로 해줘도 된다는 것!! key, value는 MDC에서 설정해주는 거임~~

 

 

AOP 설정 까지!!

@Before("@annotation(piglin.swapswap.global.annotation.SwapLog)")
    public void swapLog(JoinPoint joinPoint) {

        MDC.put("traceId", UUID.randomUUID().toString());

        HttpServletRequest req = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();

        log.info("\nMethod - {} | Method Argument - {}\nIP - {} | Browser - {}\n▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ Cookie ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼ ▼\n{} \n▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲ ▲",joinPoint.getSignature().getName(), joinPoint.getArgs(), getRemoteAddr(req), getBrowser(req),
                getCookie(req));
    }

    @AfterReturning("@annotation(piglin.swapswap.global.annotation.SwapLog)")
    public void swapLogAfterReturning() {

        MDC.clear();
    }

    @AfterThrowing(value = "@annotation(piglin.swapswap.global.annotation.SwapLog)", throwing = "exception")
    public void swapLogAfterThrowing(Exception exception) {

        log.error("errorCause - ", exception.getCause());
        MDC.clear();
    }

 

MDC는 slf4j 껄로 import 받구 아까 logback에 입력해준 키랑 밸류 뭐 넣을 건지 정해주면됨~~ uuid로 했음!! 100년동안 1초에 10억번 생성해도 겹칠확률 50%라나 뭐라나~~ 안겹치는 traceId를 만들기 위해서~~

 

이렇게하면 중요로직에서 발생한 오류가 뭔지 알고!! 어떻게 되어가고 있는지 추적이 더 확실하게 가능해졌다!

 

MDC 클리어를 해주는 이유는 Spring MVC는 쓰레드 풀(Tread Pool)에 쓰레드를 생성하여 요청이 들어오면 쓰레드를 할당해 처리하고 반납하는데 MDC는 쓰레드 별로 저장되는 Tread Local을 사용해서 클리어를 해주지 않으면 재사용 할 때 이전 데이터가 남아있으면서 데이터 혼동이 생길 수 있기 때문이다~~

 

 

결과 입니다~~ 짜란~~

위에 있는 traceId 비어져있는 이유는!! 저 부분은 어노테이션 단 부분이 아니기 때문~~~