MDC를 이용해 로그 쉽게 파악하기 : API Codes

지난 포스팅에서는 MDC(Mapping Diagnostic Context)를 이용하여 트랜잭션에 ID를 생성하고 이를 통해 로그 파악을 쉽게 하는 방법에 대해 기술해보았습니다.
오늘은 아주 조오금 더 쉽게 로그를 파악하기 위해서 MDC Filter를 이용해보도록 하겠습니다.😃

만들게 된 이유 🧐

제가 현재 맡고 있는 프로젝트는 규모가 크진 않지만 실서비스가 이뤄지고 있기 때문에 화면에서 어떤 API를 호출했고 어떤 값을 던져줬는지에 대해 파악하는 경우가 많았습니다.

화면과 저희 서버는 API 정의서를 통해 규격대로 데이터를 교환하고 있으며 각 API에는 API Code가 존재하고 있습니다. 예를 들어 주문은 CCN-001, 주문가능여부 조회 CCN-002 요런식으로 이뤄져 있습니다.

API Code가 존재하고 있기 때문에 이를 활용하여 로그를 출력하면 좀 더 이슈파악이 빠르겠다는 생각에 만들어 보았습니다. 혹시 문제가 되는 부분이 있다면 댓글로 달아주세요 🤗

⚙️ MDC 사용을 위한 환경설정

지난 포스팅과 동일하게 Log4j 디펜던시를 추가해줍시다.

parent 는 버젼확인을 위해 기재했습니다. 굳이 모든 디펜던시를 같은 버전으로 하실 필요는 없습니다.

<parent> <!-- 현재 제가 사용하고 있는 parent 디펜던시 버전입니다. -->
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-parent</artifactId>
    <version>2.6.4</version>
    <relativePath/> <!-- lookup parent from repository -->
</parent>

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-logging</artifactId>
</dependency>

✅ MDC Mapping값 사용을 위한 Key값 추가

타입세이프하게 enum으로 만들어줍시다.

public enum MDCKey {
    TRX_ID("trxId"),API_CODE("apiCode");

    @Getter
    private String key;

    MDCKey(String key) {
        this.key = key;
    }
}

✅ API Code 값을 저장하기 위한 Annotation 생성

각 컨트롤러별 API Code가 지정되고 그 값을 어노테이션 value에 저장합니다.

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface ApiCode {
    String value() default "anonymous";
}

생성된 어노테이션을 컨트롤러에 적용해봅시다!

// e.g
@ApiOperation("JCK-101 조회하기 [테스트용]") // Swagger를 위한 어노테이션 - 생략가능
@GetMapping("/find")
@ApiCode("JCK-101")
public BasePayload methodOne(@RequestParam @Valid @ApiParam("조회 정보") JacksonRequest jacksonRequest){
    return channelManager.findJackson(jacksonRequest);
}

✅ Filter 생성하여 MDC 적용

@Component
@Slf4j
@RequiredArgsConstructor
public class ApiCodeFilter extends OncePerRequestFilter {

    private final HandlerMapping handlerMapping;

    @SneakyThrows
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        HandlerExecutionChain chain = handlerMapping.getHandler(request);
        if(!ObjectUtils.isEmpty(chain)){
            HandlerMethod handlerMethod = (HandlerMethod) chain.getHandler();
            final ApiCode annotation = handlerMethod.getMethod().getAnnotation(ApiCode.class);
            if(!ObjectUtils.isEmpty(annotation)){
                MDC.put(API_CODE.getKey(), annotation.value());
                log.info("-- {} --", annotation.value());
            }
        }
        filterChain.doFilter(request, response);
        MDC.remove(API_CODE.getKey());
    }
}

• OncePerRequestFilter : 사용자 요청에 한번만 호출될 것이기 때문에 OncePerRequestFilter를 사용했습니다. (일반 Filter나 GenericFilter를 사용할 경우 두번 호출되는 경우도 발생할 수 있습니다.)
• HandlerMapping : Spring MVC에서 Servlet request에 대해 url과 매칭되는 handler를 선택해주는 클래스입니다. 이후 받아온 Handler에서 annotation value를 가져옵니다.
• MDC : ThreadLocal에 key 값과 함께 annotation value를 저장해줍니다. 필터가 끝날 때 remove를 통해 할당된 API Code지워주셔야 추후 Thread가 재활용 되었을 때 유효하지 않은 API Code가 출력되는 것을 막아줄 수 있습니다.

기존에 Filter에서는 당연히 Bean을 사용할 수 없다고 생각하여 Interceptor에서 구현했으나 Spring 1.2 부터 구현된 DelegatingFilterProxy 덕분에 Bean으로 등록하여 사용할 수 있다는 것을 알게되어 Filter에서 다른 빈(HandlerMapping)을 가져와 사용하게 되었습니다.

💡Spring 2.6.X 버전에서의 주의사항

: Spring 2.6 이상 버전에서는 Matching-Strategy의 Default값이 AntPathMatcher에서 PathPatternParser로 변경되어 기존의 String으로 된 URL와 HandlrMapping을 사용하여 Handler를 가져오는 방식이 더이상 동작하지 않습니다. 그렇기 때문에 Properties에 설정값으로 변경해주셔야 위의 필터가 기능할 수 있습니다.

spring.mvc.path-match.matching-strategy=ANT_PATH_MATCHER

✅ Logback에 저장해주기

<configuration scan="true" scanPeriod="30 seconds">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>
                            [%d{HH:mm:ss.SSS}][%-5level][%logger{36}.%method:line%line][%X{trxId}] **%X{apiCode}** - %msg%n
                        </pattern>
        </encoder>
    </appender>
    <root name="org.springframework" level="info" additivity="false">
        <appender-ref ref="STDOUT" />
    </root>
    <logger name="org.springframework.web.filter" level="debug">
    </logger>
</configuration>

• 마지막으로 원하는 위치에 %X{apiCode}를 추가해줍시다.

👏🏻 결과 👏🏻

마지막으로 Postman이나 Swagger 등을 통해 요청을 넣어주시면!

이렇게 하나의 트랜잭션이 시작됐을 때부터 어떤 API가 호출되었는지 알 수 있습니다.

활용

아니 트랜잭션 아이디랑 이게 무슨 차이가 있지? 라고 생각하실 수 있다고 생각합니다.

제가 맡고있는 프로젝트는 실시간으로 고객의 주문이나 결제가 들어오고 있기 때문에 지정된 시간이 클라이언트가 어떤 API를 호출하였는지 파악하기 쉬워진다면 하나의 주문건에 대한 히스토리를 파악하기 쉬워집니다.

또한 실시간 테스트를 하는 경우

tail -f jacksonLog.2022-04-16.log | grep "{apiCode}"

이런 식으로 입력하나면 하나의 트랜잭션을 바로 파악할 수 있습니다.

결론

오늘은 MDC 필터와 Servlet-HandlerMapping 구조를 활용한 API Code Logging filter를 만드는 방법에 대해 알아보았습니다. 다음시간에는 좀 더 유용한 기능을 가지고 돌아오도록 하겠습니다. 질문과 태클은 환영합니다!