Spring MVC Stack - Logging With AOP + MDC

Spring Application 개발 간에 더 유의미한 로깅을 남기기 위한 AOP + MDC 를 활용 방법에 대하여 알려 드리겠습니다:D

 

Spring MVC 를 사용하여 Application 개발을 진행하는 경우, Request/Response를 로깅하기 위해서 AOP 를 통해 공통된 Tracing ID를 설정하고 로그를 남기고 하나의 Context에 대하여 추적이 가능하도록 개발하며, 이를 통해 더 유의미한 로그를 남기고 있습니다.

 

그리고 Request/Response에 대한 로깅 뿐만 아니라 해당 Context 내의 로직 수행 시에 info, error 로그도 추적을 편하게 하기 위하여 Tracing ID를 로그에 같이 찍는 방법이 있습니다. 

 

이를 조금더 편하게 하기 위하여, JAVA 로깅 프레임워크(logback, log4j,,) 에서는 MDC 라는 기능을 제공하고, 이 값을 통해 로그 메시지에 해당 값이 자동으로 찍히도록 설정 할 수 있습니다.

 

- MDC(Mapped Diagnostic Context ) 

logback, log4j 등 JAVA에서 제공하는 로그 관련 라이브러리에서 여러 메타 정보를 넣을 수 있고 공유되는 Map으로 key, value 형식으로 저장하고 사용 가능.

 

AOP + MDC 를 통한 Request/Response + Logic 로그 출력 내용

 

0. 개발 환경 : Spring Boot 2.4.x, JAVA8 

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

 

1. 로그 출력 포맷 설정

• trace.id를 출력하기 위하여 출력 포맷에 [trace.id=%X{trace.id}] 추가

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="5 minutes" debug="false">
  <property name="console.format"
    value="* %-20(%cyan(%date{HH:mm:ss.SSS}) [%thread] [trace.id=%X{trace.id}]) %highlight(%-5level) %magenta(%marker|%logger{36}): %msg%n%rEx"/>

  <!-- console -->
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>${console.format}</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="CONSOLE"/>
  </root>

</configuration>

 

2. AOP 및 MDC Tracing ID Setting

- Controller를 통해 들어온 Request/Response를 AOP @Berfore, @AfterReturning으로 각각 로깅 처리

- @Before 에서 공통적으로 사용할 Tracing ID를 MDC에 추가 / MDC.put("trace.id", UUID.randomUUID().toString())

- @AfterReturning/@AfterThrowing 에서 MDC Clear 처리 / MDC.clear() 

public class LogConstant {
  public static final String TRACING_ID = "trace.id";
}

import com.sample.springmvclogging.constant.LogConstant;
import java.util.UUID;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;

@Slf4j
@Aspect
@Component
public class SampleAspect {

  @Pointcut("execution(* com.sample.springmvclogging.application.controller.*.*(..) )")
  public void controllerAdvice() {
  }

  @Before("controllerAdvice()")
  public void requestLogging(JoinPoint joinPoint) {

    // MDC Tracing id Setting
    MDC.put(LogConstant.TRACING_ID, UUID.randomUUID().toString());

    // Logging REQUEST Info's,,,,
    log.info("REQUEST ::: TRACING_ID ::: {}", MDC.get(LogConstant.TRACING_ID));
  }

  @AfterReturning(pointcut = "controllerAdvice()", returning = "returnValue")
  public void requestLogging(JoinPoint joinPoint, Object returnValue) {

    // Logging RESPONSE Info's,,,,
    log.info("RESPONSE ::: RESULT ::: {}", returnValue);

    // MDC Clear
    MDC.clear();
  }
}

 

3. Controller, Service Class

@GetMapping("/{id}")
  public String get(@PathVariable int id) {
    log.info("IN Controller, Do something....");
    return sampleService.doSomething(id);
  }

@Slf4j
@Service
public class SampleService {

  public String doSomething(int id) {
    String result = "User Id is " + id;
    log.info("IN Service, result is {}", result);

    return result;

  }
}

4. 로깅 출력 결과

- AOP를 통해 Request/Response 로깅 뿐만 아니라, 로직 내의 info 성 로그도 같은 trace.id 를 하나의 Context내의 로그 확인 가능

* 13:51:56.751 [http-nio-8080-exec-1] [trace.id=254cae59-7dba-4f03-9873-fd1beeac695e] INFO  |c.s.s.aspect.SampleAspect: REQUEST ::: TRACING_ID ::: 254cae59-7dba-4f03-9873-fd1beeac695e
* 13:51:56.763 [http-nio-8080-exec-1] [trace.id=254cae59-7dba-4f03-9873-fd1beeac695e] INFO  |c.s.s.a.controller.SampleController: IN Controller, Do something....
* 13:51:56.763 [http-nio-8080-exec-1] [trace.id=254cae59-7dba-4f03-9873-fd1beeac695e] INFO  |c.s.s.a.service.SampleService: IN Service, result is User Id is 1
* 13:51:56.764 [http-nio-8080-exec-1] [trace.id=254cae59-7dba-4f03-9873-fd1beeac695e] INFO  |c.s.s.aspect.SampleAspect: RESPONSE ::: RESULT ::: User Id is 1

하나의 요청/응답 로깅 출력 결과

5. 마치며

AOP+MDC 를 활용하여 하나의 요청 Context에 따른 Request/Response 값 뿐만 아니라 로직내에서 남기는 로깅도 같은 Tracing ID 를 남기게 하여, 보다 유의미한 로그 작성 및 서비스 운영 간에 이슈 추적이 가능하게 되었습니다.

추가적으로 MSA 환경에서 분산 Tracing 관련해서는 Spring Cloud Sleuth 를 참고하시면 좋을 것 같습니다.

 

그리고 다음 글에는 Spring Reactive Stack(WebFlux) 환경에서 쓰레드 변경에 따른 로깅 추적의 어려움을 MDC를 활용하여 해결하는 내용 공유 드리도록 할게요:D  

 

소스 코드 : github.com/lucia8918/spring-mvc-mdc-logging