MDC 및 로그레벨에 따른 로그파일 분리

(1) 문제점

 

멀티쓰레드 환경에서 동시에 요청이 처리되기 떄문에 동일한 요청에 대한 로그가 연속적으로 쌓이는 것이 아니라 처리된 순서대로 로그가 쌓이는것을 볼 수 있다. 만약 서비스에 문제가 생겨 로그파일을 보려고 할때 쉽게 문제를 찾기 위해서는 동일한 요청을 분리하는 작업이 필요하다.  위의 문제를 해결하기위해서는 요청별로 고유의 값을 부여하고 로그에 함꼐 출력한다면 동일한 요청을 분리하는 작업이 매우 간단해 질 것이다. 

 

(2) MDC를 이용한 해결방안

1. MDC란

MDC(Mapped Diagnostic Context)는 현재 실행중인 쓰레드에 메타 정보를 넣고 관리하는 공간이다.

MDC는 내부적으로 Map을 관리하고 있어 (Key, Value) 형태로 값을 저장할 수 있다.

메티 정보를 쓰레드 별로 관리하기 위해 내부적으로는 쓰레드 로컬을 사용하고 있다.

스프링 애플리케이션에서는 요청(Request)이 오면 MDC에 uuid를 넣고 로그에 이를 포함시키면 된다.

 

2. MDC filter

@Order(Ordered.HIGHEST_PRECEDENCE) //필터의 가장 앞 단
@Component
@Slf4j
public class MdcFilter implements Filter {
    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        UUID uuid = UUID.randomUUID();
        MDC.put("request_id",uuid.toString());
        chain.doFilter(request,response);
        MDC.clear();
    }
}

 

요청이 들어오면 MdcFilter를 filter의 가장 앞단에 두어 MDC에 uuid를 넣고 로그에 포함시킨다.

그리고 doFilter가 끝나면  MDC에 있는 정보를 삭제시켜주어야 한다. 만약 삭제를 시키지 않을 경우 다른 요청이 MDC가 쓰인 쓰레드를 사용할 때 MDC에 있던 정보가 재사용 될 수 있다.

 

3. logback-spring.xml - 로그 출력 부분

<property name="LOG_CONSOLE_PATTERN" value="%highlight(%-5level) %d{yy-MM-dd HH:mm:ss} [%thread]  [%logger{0}:%line] [%X{request_id:-startUp}] - %msg%n"/>

 

이제 MDC에 저장한 uuid를 로그에 출력하여야 한다. 여기서 로그 출력 패턴을 보면 %X{request_id: -startUp}부분이 MDC에서 저장햇던 uuid를 로그에 출력하는 부분이다. -startUp은 request_id 가없을시 startUp이 출력된다.

 

4. loback-spring.xml  및 로그레벨에 따른 파일 분리

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <!-- 로그 파일이 저장될 경로 -->
    <property name="LOG_INFO_PATH" value="C:/Users/My PC/log/INFO"/>
    <property name="LOG_WARN_PATH" value="C:/Users/My PC/log/WARN"/>
    <property name="LOG_ERROR_PATH" value="C:/Users/My PC/log/ERROR"/>

    <!-- 로그 출력 패턴 -->
    <property name="LOG_CONSOLE_PATTERN" value="%highlight(%-5level) %d{yy-MM-dd HH:mm:ss} [%thread]  [%logger{0}:%line] [%X{request_id:-startUp}] - %msg%n"/>
    <property name="LOG_FILE_PATTERN" value="%-5level %d{yy-MM-dd HH:mm:ss} [%thread]  [%logger{0}:%line] [id = %X{id}] - %msg%n"/>
    <property name="LOG_LEVEL" value="info"/>

    <!-- 로그 레벨 -->
    <!--
    	1) ERROR : 오류 메시지 표시
        2) WARN  : 경고성 메시지 표시
        3) INFO  : 정보성 메시지 표시
        4) DEBUG : 디버깅하기 위한 메시지 표시
        5) TRACE :  Debug보다 훨씬 상세한 메시지 표시

        INFO 일 경우 INFO 보다 위에 있는 DEBUG와 TRACE는 표시하지 않는다.
    -->

    <!-- CONSOLE에 로그 출력 세팅 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                ${LOG_CONSOLE_PATTERN}
            </Pattern>
        </layout>
    </appender>

    <!-- File에  INFO 로그 출력 세팅 -->
    <appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 레벨 필터 설정 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
            <onMismatch>DENY</onMismatch>
        </filter>
        <!-- 출력패턴 설정-->
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_FILE_PATTERN}</pattern>
        </encoder>
        <!-- Rolling 정책 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- .gz,.zip 등을 넣으면 자동 일자별 로그파일 압축 -->
            <fileNamePattern>${LOG_PATH}/INFO.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최고 용량 kb, mb, gb -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- 일자별 로그파일 최대 보관주기(~일), 해당 설정일 이상된 파일은 자동으로 제거-->
            <maxHistory>30</maxHistory>
            <!--<MinIndex>1</MinIndex>
            <MaxIndex>10</MaxIndex>-->
        </rollingPolicy>
    </appender>

    <!-- File에  WARN 로그 출력 세팅 -->
    <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 레벨 필터 설정 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
            <onMismatch>DENY</onMismatch> <!-- 다른 수준의 레벨은 기록하지 않는다.(상위 레벨도 기록 안함), 상위 수준의 레벨에 대한 기록을 원하면 ACCEPT 로 하면 기록된다. -->
        </filter>
        <!-- 출력패턴 설정-->
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_FILE_PATTERN}</pattern>
        </encoder>
        <!-- Rolling 정책 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- .gz,.zip 등을 넣으면 자동 일자별 로그파일 압축 -->
            <fileNamePattern>${LOG_PATH}/warn.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최고 용량 kb, mb, gb -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- 일자별 로그파일 최대 보관주기(~일), 해당 설정일 이상된 파일은 자동으로 제거-->
            <maxHistory>30</maxHistory>
            <!--<MinIndex>1</MinIndex>
            <MaxIndex>10</MaxIndex>-->
        </rollingPolicy>
    </appender>

    <!-- File에  ERROR 로그 출력 세팅 -->
    <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!-- 레벨 필터 설정 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
            <onMismatch>DENY</onMismatch> 
        </filter>
        <!-- 출력패턴 설정-->
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_FILE_PATTERN}</pattern>
        </encoder>
        <!-- Rolling 정책 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- .gz,.zip 등을 넣으면 자동 일자별 로그파일 압축 -->
            <fileNamePattern>${LOG_PATH}/error.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최고 용량 kb, mb, gb -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- 일자별 로그파일 최대 보관주기(~일), 해당 설정일 이상된 파일은 자동으로 제거-->
            <maxHistory>30</maxHistory>
            <!--<MinIndex>1</MinIndex>
            <MaxIndex>10</MaxIndex>-->
        </rollingPolicy>
    </appender>

    <root level="${LOG_LEVEL}">
        <!-- 위에 설정한 콘솔 설정 추가 -->
        <appender-ref ref="CONSOLE"/>
        <!-- 위에 설정한 파일 설정 추가 -->
        <appender-ref ref="INFO_FILE"/>
        <appender-ref ref="WARN_FILE"/>
        <appender-ref ref="ERROR_FILE"/>
    </root>

</configuration>

 

로그를 관리 할때 로그레벨에 따라서 파일로 분리 할 경우 문제가 일어났을때 ERROR 로그파일만 열어서 로그를 확인하면 되므로 매우 편리하다. 만약 모든 로그레벨이 섞여있는 파일에서 ERROR로그만 찾으려고 할 경우 매우 많은 시간이 걸릴 것이다.

 

5. 결과

 

log에서 uuid를 통해 동일한 요청을 분리하기 쉬워진것을 볼 수 있다.