logback으로 런타임 시 로깅을 동적으로 분리하는 방법

사내 프로젝트 중, 제휴 API 서버 로그를 제휴사별로 분리해야될 필요가 있었다.
일반적으로 사용되는 RollingFileAppender가 아닌, 런타임 시 로깅을 동적으로 분리해주는 SiftingAppender로 래핑하여 사용하였다.

1. logback 설정

<!-- SIFT FILE Appender -->
<appender name="SIFT_FILE" class="ch.qos.logback.classic.sift.SiftingAppender">
  <discriminator>
    <key>path</key>
    <defaultValue>application/application</defaultValue>
  </discriminator>
  <sift>
    <!-- FILE Appender -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${LOG_PATH}/${path}.log</file>
      <!-- 일자별로 로그파일 적용하기 -->
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${LOG_PATH}/${path}_%d{yyyyMMdd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <!-- 일자별 백업파일의 보관기간 -->
      </rollingPolicy>
      <encoder>
        <charset>UTF-8</charset>
        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p}\(${PID:- }\)[%t] [%logger{30}:%line] [${ACTIVE_PROFILES}] %msg%n</pattern>
      </encoder>
    </appender>
  </sift>
</appender>

맨 위에 있는 discriminator 태그 안에 있는 key 태그 값은 소스 코드에서 지정할 수 있다.
만약 지정 하지 않게 되면 defaultValue 태그 안에 있는 값을 사용한다. 이 값은 spring boot application 로그 경로로 사용된다.

2. MDC를 이용한 경로 지정

소스 코드에서 key를 지정하는 방법은,
SiftingAppender 에서 사용한 key 명칭을 MDC map의 key로 사용하고 value에는 동적으로 변경할 로그 경로를 지정하여 put 해주면 된다.
MDC는 Mapped Diagnostic Context의 약자로, 멀티 클라이언트 환경에서 다른 클라이언트와 값을 구별하여 로그를 추적할 수 있도록 제공되는 map 이라고 한다.
다수의 요청이 들어왔을 때 로그가 뒤섞이는 문제를 해결하는 데 사용하기 적합해 보인다.

import org.slf4j.MDC;
...
// 옥션 비즈니스 로직 실행
MDC.put("path", String.join("/", "auction", "order-auction"));
ebayFacade.exec(EnterpriseCode.AUCTION);

// 지마켓 비즈니스 로직 실행
MDC.put("path", String.join("/", "gmarket", "order-gmarket"));
ebayFacade.exec(EnterpriseCode.GMARKET);

위와 같이 지정하면 auction 기준으로 “${LOG_PATH}/auction/order-auction_20230130.log” 로깅파일이 생성된다.
어떤 코드 위치에서든지 같은 스레드상이라면, MDC key 값을 한번 지정해주는 것으로 경로 공유가 가능하다.
옥션 MDC key를 지정한 이후에는 log로 찍는 내용들이 다 “auction/order-auction” 경로에 저장되며,
지마켓 MDC key를 지정한 이후에는 log로 찍는 내용들이 다 “gmarket/order-gmarket” 경로에 저장되는 것이다.

3. 비동기 처리 이슈

그렇게 서비스해 놓고 보니, 한 가지 문제점이 발견되었다.
제휴사와 API 비동기 호출 처리 시 남기는 로그는 MDC가 제대로 동작하지 않는 것이다.
이유는 메인, 서브 스레드끼리는 MDC Context가 공유되지 않기 때문이다.

해결방법으로는 메인 스레드의 MDC Context를 저장했다가 서브 스레드 스코프에서 이를 setContextMap() 처리하는 방법이 있다.
참고로 requestDelivery() 메소드의 두번째 인자는 서브 스레드가 API callback 비동기 처리하는 consumer 영역이다.

Map<String, String> parentMdc = MDC.getCopyOfContextMap();
ebayDeliveryRequestService.requestDelivery(deliveryReqDto, deliveryResDto -> {
    MDC.setContextMap(parentMdc);
    ...
});

하지만 이렇게 하더라도 메인, 서브 스레드의 로그 내용이 뒤섞여서 알아보기 어렵기 때문에,
서브 스레드(비동기 처리)에서 사용할 로깅 경로는 메인 스레드(동기 처리)와 다르게 사용하도록 처리했다.
경로 중간에 “nio” 를 더 넣었으며, 파일 이름에도 스레드명을 추가로 넣었다.

ebayDeliveryRequestService.requestDelivery(deliveryReqDto, deliveryResDto -> {
    MDC.put("path", String.join("/"
        , enterpriseName, "nio", String.join("-"
        , "order", enterpriseName, Thread.currentThread().getName())));
    ...
});

이렇게 로깅을 세분화하니 각 제휴사별 프로세스 흐름은 파악하기 쉬웠지만,
워낙 많은 파일들을 남기다보니 한눈에 볼 수 없는 단점이 존재한다.

아 그래서 ELK 스택을 세팅하는구나 하고 깨달았다ㅠ
필요성을 느끼니 공부의 동기부여도 되고 좋구나!