logback-spring.xml을 사용해 로그 커스터마이즈하기

Interceptor에서 로그 생성, yml 파일로 별도 저장 설정하기

 

스프링에서 요청과 응답이 어떻게 처리되었는지 간단하게 기록을 남기고 싶었다.

AOP를 사용할 수도 있지만 나는 Interceptor의 preHandle()과 postHandle()를 통해 로그를 남기는 방법을 선택했다.

아래와 같이 interceptor를 만들고 @Configuration이 붙은 파일에서 Interceptor를 추가하였다.

 

public class LoggingInterceptor implements HandlerInterceptor {

    private final Logger logger = LoggerFactory.getLogger(this.getClass().getSimpleName());

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws
        Exception {
        logger.info("request: {} {}", request.getMethod(), request.getRequestURI());
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
        ModelAndView modelAndView) throws Exception {
        logger.info("response: {}", response.getStatus());
    }
}

이것으로 요청이 어떤 URI와 메서드로 들어왔는지, 그리고 응답의 status code가 어떤 것인지 간단히 출력해 볼 수 있다.
구체적으로 로그를 남기고 싶다면 더 상세한 정보를 기록하면 되나, 바디에 담긴 stream을 interceptor에서 소비해 버린다면 핸들러 메서드까지 내용이 전달되지 않는 점을 유의해야 한다. 바디를 필터, 혹은 인터셉터에서 읽고자 한다면 `ContentCachingRequestWrapper` 에 대해서 찾아보면 된다.

위의 설정대로라면 로그는 콘솔창에 남겨지는데 이대로라면 웹앱이 꺼진다면 어떤 요청과 응답이 처리되었는지 알 수 없다.

아래처럼 application.yml을 간단히 설정하면 로그가 application.log라는 파일에 모두 기록되는 것을 볼 수 있다.

 

logging:
  file:
    name: application.log

콘솔에 출력되던 결과가 아래와 같이 application.log에 저장된다.

 

 

logback-spring.xml 파일 사용하기

yml로도 로그 레벨에 따른 설정, 특정 내용의 필터링 등은 가능하지만 
로그를 분류해 다른 처리를 한다거나 로그를 복잡하게 필터링하는 등의 기능은 조금 아쉽다.

이제 slf4j의 구현체인 logback에 대한 설정파일을 통해 이 인터셉터에서 나타나는 로그만을 파일로 남기도록 처리해보겠다.
spring에서도 공식적으로 logback을 채택하여 사용하고 있어 `spring-boot-starter`와 관련된 의존성을 사용한다면 이 기능을 바로 사용할 수 있다.

logback에 대한 설정은 기본적으로 xml을 통해 설정하도록 되어있으며, application.yml과 같은 resources 폴더에 위치시키면 된다.
logback-spring.xml은 application.yml의 로그 관련 설정보다 우선한다.

다음은 위에서 정의한 Interceptor에서 발생한 로그만 `logFile.log`에 남기도록 하는`logback-spring.xml`이다.

<configuration>
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>logFile.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>

        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <logger name="LoggingInterceptor" additivity="false">
        <level value = "INFO" />
        <appender-ref ref="FILE" />
    </logger>
</configuration>

설정 내용은 크게 appender를 정의하는 부분과 logger를 정의하는 부분으로 나뉜다.
복잡해 보이지만 천천히 살펴보면 내용이 많지 않다.

 

 

appender - policy

먼저 appender는 실제 로그에 대한 작성 책임을 가진다.

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>logFile.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
        <maxHistory>30</maxHistory>
        <totalSizeCap>100MB</totalSizeCap>
    </rollingPolicy>

    <encoder>
        <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
    </encoder>
</appender>

 

appender의 종류는 여럿이 있는데 여기서는 RollingFileAppender를 선택했다.

여기서 Rolling은 로그 파일의 크기 혹은 시간에 따라 교체가 가능함을 의미한다.

 

파일의 경로 및 이름을 <file></file> 내부에 정의할 수 있다.

또한 <rollingPolicy></rollingPolicy>를 통해 어떤 기준으로 로그를 교체할지 정책을 정할 수 있다.

 

여기서는 시간을 기준으로 rolling 하는 TimeBasedRollingPolicy를 선택하였다. (시간과 파일 크기 모두를 고려하는 정책도 존재한다)

이 설정대로라면 하루에 한 번 기존의 로그의 이름을 변경, 총 30일간의 로그를 기록하며 로그 파일들이 용량이 100MB가 넘어가면 가장 오래된 로그부터 삭제한다.

 

로그 파일이 rolling 될 주기는 fileNamePattern에 적힌 yyyy-MM-dd와 같은 형식을 통해 지정된다.

위의 설정은 rolling의 최소 단위가 날짜(dd)이므로 하루에 한 번 파일이 분리되고,

아래와 같이 yyyy-MM-dd:ss.SSS로 미리초 단위로 지정하면 최신 로그는 logFile.log에, 과거의 로그는 미리초까지 시간을 붙여 별도로 저장되는 것을 볼 수 있다.

 

 

appender - encoder

 

다음은 encoder, 어떤 형식으로 로그를 출력할지에 대한 레이아웃을 지정하는 부분이다.

 

<encoder>
    <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
</encoder>

 

각 표현의 %-n 부분은 정보가 최소 n글자로 표시, 오른쪽 정렬됨을 의미한다.

relative는 작성 중인 로그 파일의 첫 번째 로깅 이벤트부터 경과한 시간을 밀리초 단위로 표시,

thread는 해당 이벤트가 어떤 스레드에서 발생했는지,

level은 어떤 수준의 이벤트인지,

logger는 이벤트를 발생시킨 로거의 이름을 의미한다. (여기서는 맨 위의 Interceptor에서 아래와 같은 코드를 통해 로거를 만들었으므로, 로거의 이름은 getLogger()에 들어간 패키지가 미포함된 클래스의 이름인 LoggingInterceptor)가 된다.

 

private final Logger logger = LoggerFactory.getLogger(this.getClass().getSimpleName());

 

-%msg를 통해 로그 메시지를 출력하고, %n을 통해 개행 문자를 출력한다.

 

 

logger

 

마지막으로 logger에 대한 설정 부분은 아래와 같다.

 

<logger name="LoggingInterceptor" additivity="false">
    <level value = "INFO" />
    <appender-ref ref="FILE" />
</logger>

 

나는 로그 중 LoggingInterceptor라는 내용이 포함된 부분만을 별도로 뽑아내고 싶으므로, 해당 내용이 포함된 내용만을 선택한다.

이 중 INFO 이상의 로그만을 선별하여 위에서 설정한 appender인 "FILE" appender를 통해 로그를 기록하도록 지정한다.

 

여기서 name 속성의 내용을 통해 로그의 내용을 선별할 수 있다. 길이 혹은 패턴 매칭을 통해 원하는 내용이 들어간 로그만 선별이 가능하다.

 

 

 

위의 설정을 통해서 요청 URI와 Method, 응답 status code만이 별도의 파일로 기록되는 것을 확인하였다.

 

 

 

여러 appender로 로그를 다르게 처리하기

 

여러 appender와 logger들을 통해 로그를 다양하게 찍어낼 수 있다.

예를 들어 위의 설정에서는 기존에 콘솔에 뜨던 로그는 더 이상 뜨지 않는다.

 

원래처럼 모든 로그를 console에 띄우고, LoggingInterceptor 로거에서 발생하는 로그만 별도의 로그 파일에 저장하는 설정 파일은 아래와 같다.

 

<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>.log/logFile.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./log/logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>100MB</totalSizeCap>

        </rollingPolicy>

        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>


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

    <logger name="LoggingInterceptor" additivity="false">
        <level value = "INFO" />
        <appender-ref ref="FILE" />
    </logger>
</configuration>

 

두 개의 appender를 사용, 기존과 다른 하나는 ConsoleAppender로 콘솔에 로그를 출력한다.

INFO 이상의 로그는 모두 ConsoleAppender를 사용해 콘솔에 출력하도록 하며 LoggingInterceptor에 대한 로그는 기존과 같이 별도로 처리한다.

 

 

긴 logback-spring.xml 분리하기

 

로그를 다양하게 나눠 찍어야 한다면 로그 설정 파일이 매우 길어질 것이다.

위의 로그 파일을 분리하여 효율적으로 관리할 수도 있다.

 

<!-- logback-spring.xml -->

<configuration>
    <include resource="console_appender.xml" />
    <include resource="file_appender.xml" />

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

    <logger name="LoggingInterceptor" additivity="false">
        <level value="INFO" />
        <appender-ref ref="FILE" />
    </logger>
</configuration>

 

<!-- console_appender.xml -->

<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
</included>

 

<!-- file_appender.xml -->

<included>
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>.log/logFile.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./log/logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
            <totalSizeCap>100MB</totalSizeCap>
        </rollingPolicy>

        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
    </appender>
</included>

 

어떤 로그를 어떻게 남길지는 서비스에 따라 달라지는 중요한 요구사항이다.

이처럼 logback의 설정 파일을 사용하면 원하는 로그를 원하는 방식으로 나누어 저장할 수 있다.