Post

Logback으로 로깅 시스템 설정하기

애플리케이션의 로그를 파일로 기록하고, 발생한 문제를 빠르게 파악하기 위해서 로깅시스템을 구현하였습니다.

Posted
By Jaehoon
21 min read

로깅 시스템 구축의 필요성

지금까지 로그는 개발 과정에서 콘솔로 찍어가며 데이터의 흐름을 파악하거나 디버깅하는 용도로 사용했다. 하지만 최근들어 서비스를 사용하는 유저가 많아지면서 악의적인 요청을 보내거나 개발 단계에서 고려하지 못한 요청 케이스로 서버에서 예외가 발생하는 경우가 생겼다. 문제가 발생했을 때 로그를 따로 저장해두지 않았기 때문에 문제 원인을 파악하기 위해 직접 QA를 해보며 로컬에서 디버깅을 할수 밖에 없었다. 하지만 문제의 발생횟수가 늘어나자 원인을 파악하는데에 시간을 많이 쏟게 되었고, 내가 파악한 원인이 정답인지도 의구심이 생겼다. 또 문제가 발생한 직후 알아차릴 수 없다는 문제도 있었다. 주먹구구식으로 문제를 파악하는 식으로 운영했기 때문에 문제발생 시간 이후 이미 오랜시간이 지난 경우가 많았다.

  • 로그를 파일로 저장했다면 문제가 발생한 시점의 로그를 보고 정확한 원인을 파악할 수 있었을 것이고
  • 슬랙이나 메일로 알림을 받을 수 있었다면 문제를 빠르게 인지할 수 있었을 것이다.

Logback

스프링 부트 스타터 라이브러리를 프로젝트에 포함시켰다면 기본값으로 Logback을 사용하게 된다. 흔히 @Slf4j 애노테이션을 적용시켰을 때 기본으로 적용되는 로그 라이브러리가 Logback이다. Log4j를 사용하도록 설정할 수 있지만 두 로그 라이브러리의 개발자가 같고, Log4j를 개선시켜 만들어낸 것이 Logback 이기 때문에 특별한 이유가 없다면 기본으로 주어지는 Logback을 사용하게 된다.

어떻게 설정하는가

Logback 설정은 application.properties 나 application.yml 같은 설정파일에서 수행할 수도 있고, resources 폴더에 logback.xml, logback-spring.xml 파일에 세부적인 설정을 할 수 있다.

나는 로그 레벨별로 파일을 분리하고, 슬랙에 메세지를 비동기로 보내는 등 세부설정을 할 예정이기 때문에 .xml 파일을 사용하기로 결정했다.

목표

만들어볼 로그 시스템의 목표는 다음과 같다.

  • 로그 레벨(INFO, WARN, ERROR) 별로 로그 파일을 분리한다.
  • 로그 파일은 하루 단위로 나누어 기록되도록 한다.
  • 에러(ERROR) 로그가 발생한 경우 아래의 정보를 슬랙 메세지로 전달한다.
    • 로그 메세지
    • REQUEST_ID
    • REQUEST_URI
    • REQUEST_METHOD
    • REQUEST_TIME
    • REQUEST_IP

logback-spring.xml 파일 작성

logback-spring.xml 파일을 resources 폴더에 작성해 Logback의 세부사항을 설정할 수 있다.

logback.xml 이라는 이름으로 파일을 만들어도 적용할 수 있으나, 스프링부트 로깅 문서에는 가능하면 -spring 접미사를 붙일 것을 권장하고 있다. 더 유연성이 증가하고, 초기화 순서 관련 문제를 방지해준다고 한다.

먼저 내가 작성한 logback-spring.xml 스크립트를 먼저 보면서 하나하나 설명해보겠다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

<!-- logback-spring.xml -->
<?xml version="1.0" encoding="UTF-8"?>

<configuration scan="true">
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <timestamp key="DATE_PATTERN" datePattern="yyyy-MM-dd" />

    <include resource="console-appender.xml" />
    <include resource="info-appender.xml" />
    <include resource="warn-appender.xml" />
    <include resource="error-appender.xml" />

    <root level="info">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE-INFO" />
        <appender-ref ref="FILE-WARN" />
        <appender-ref ref="FILE-ERROR" />
        <appender-ref ref="ASYNC_SLACK" />
<!--        <springProfile name="prod">-->
<!--            <appender-ref ref="ASYNC-SLACK" />-->
<!--        </springProfile>-->
    </root>
</configuration>
  • <configuration scan="true">
    • 설정정보 작성을 시작하는 부분입니다.
    • scan 옵션은 설정 파일의 변경사항을 자동으로 감지하여 재 로딩하는 역할을 합니다.
  • <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    • 스프링 부트의 기본 로깅 설정을 포함합니다.
  • <timestamp key="DATE_PATTERN" datePattern="yyyy-MM-dd" />
    • DATE_PATTERN 라는 키로 날짜를 yyyy-MM-dd 형식으로 저장합니다.
  • <include resource="..." />
    • resource 옵션에 적힌 파일을 설정정보에 포함시킵니다.
    • 현재 코드에서는 아래의 파일들이 포함되어 있습니다.
      • 콘솔 로그 출력을 담당하는 console-appender.xml
      • INFO 레벨 로그 출력을 담당하는 info-appender.xml
      • WARN 레벨 로그 출력을 담당하는 warn-appender.xml
      • ERROR 레벨 로그 출력을 담당하는 error-appender.xml
  • <root level="info">
    • 루트 로그 레벨을 INFO로 설정한다.
  • Appender 참조
    • 정의해둔 Appender 이름을 사용해서 Appender를 추가한다.

로그 콘솔 어펜더 설정

앞으로 추가할 여러 XXX-appender.xml 파일도 전부 logback-spring.xml 파일과 같이 resources 폴더에 위치시키면 된다.

1
2
3
4
5
6
7
8
9

<!-- console-appender.xml -->
<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
</included>
  • <included> 태그는 이 설정이 다른 logback 설정파일에 포함될 수 있음을 나타냅니다.
  • <appender> 정의
    • name: appender의 이름을 CONSOLE로 설정
    • class: ch.qos.logback.core.ConsoleAppender 클래스를 지정했습니다. 로그를 콘솔에 출력하는 appender 입니다.
  • <encoder> 설정
    • 로그 메세지를 어떻게 포맷팅 할지 정의합니다.
    • <pattern> 태그로 콘솔에 출력할 패턴을 지정할 수 있습니다.
      • 여기서는 CONSOLE_LOG_PATTERN 이라는 변수를 적용했습니다. 이 변수는 스프링 부트의 기본설정에 정의되어 있는 변수이고, 우리가 스프링 부트를 애플리케이션을 실행했을 때 볼 수 있는 로그가 이 형식입니다.
    • <charset> 태그로 로그 메시지의 문자 인코딩을 지정합니다. 여기서는 UTF-8 인코딩을 지정하였습니다.

로그 파일 어펜더 설정

로그파일은 로그의 레벨별로 관리되도록 설정하였다. 로그를 레벨별로 관리한 이유는 아래와 같다.

  • 가독성이 향상된다
  • ERROR나 WARN레벨 로그만 따로 모아 볼 수 있어 중요한 문제를 신속하게 파악할 수 있다.
  • 로그 레벨의 중요도 별로 다른 보관 정책을 적용할 수 있다.

먼저 INFO레벨의 로그를 파일 롤링 정책으로 저장하는 info-appender.xml을 먼저 살펴보도록 하겠습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

<!-- info-appender.xml -->
<included>
    <appender name="FILE-INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>../logs/info/${DATE_PATTERN}.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%X{REQUEST_ID:-NO REQUEST ID}] ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n%n</pattern>
            <charset>utf8</charset>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>../log/info/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>10</maxHistory>
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>
  • <appender> 정의
    • appender의 이름(name)을 FILE-INFO로 정의 하였습니다.
    • class 로 ch.qos.logback.core.rolling.RollingFileAppender를 사용하고 있습니다.
      • 로그를 파일에 저장하고 롤링(순환) 정책을 적용하는 appender를 정의하기 위해 사용하는 클래스 입니다.
  • <file> 태그
    • 로그 파일의 위치와 이름을 지정하는 태그입니다.
    • DATE_PATTERN은 logback-spring.xml 에서 정의했던 timestamp 변수입니다.
  • <filter> 태그
    • INFO 레벨의 로그만 허용하고 다른 레벨은 거부하는 필터를 작성합니다.
    • h.qos.logback.classic.filter.LevelFilter 클래스를 적용하고 있습니다. 이 필터는 지정한 레벨의 로그만 통과시킵니다.
  • <encoder>태그
    • 로그 메세지의 형식을 정의합니다.
    • UTF-8 인코딩을 사용합니다.
  • <rollingPolicy>태그
    • 로그 파일 롤링 정책을 정의합니다.
    • ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy는 파일 크기와 시간을 기준으로 로그파일이 나누어지는 정책입니다. TimeBasedRollingPolicy는 지정한 시간을 넘어가야만 로그파일이 나누어지지만, SizeAndTimeBasedRollingPolicy는 지정한 시간을 넘어가지 않았더라도 지정한 로그파일의 최대 크기를 넘어가면 파일이 나누어집니다.
    • <fileNamePattern>: 파일 이름 패턴을 지정하는 태그
    • <maxFileSize>: 최대 파일 크기를 지정합니다. 이 크기를 넘어가면 새로운 로그파일이 만들어집니다.
    • <maxHistory>: 최대 보관할 로그 파일의 수. 이 수를 넘어가면 가장 오래된 로그 파일이 자동으로 삭제된다.
    • <totalSizeCap>: 전체 로그파일의 최대 크기
    • 서비스가 올려진 서버의 하드디스크 용량이 10GB로 적기 때문에 로그파일이 큰 용량을 차지할 수 없어 로그파일의 전체 용량을 1GB로 책정하였습니다.

다음은 WARN 레벨 파일 롤링설정이 나타나있는 warn-appender.xml 입니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

<!-- warn-appender.xml -->
<included>
    <appender name="FILE-WARN" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>../logs/warn/${DATE_PATTERN}.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>WARN</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%X{REQUEST_ID:-NO REQUEST ID}] ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n%n</pattern>
            <charset>utf8</charset>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>../logs/backup/info/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>10</maxHistory>
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>

warn-appender.xml는 info-appender.xml 과 필터링하는 레벨과 로그 파일 디렉토리 정보만 다르고 나머지 부분은 동일합니다.

슬랙 알림 어펜더 설정

다음으로 ERROR 레벨의 로그를 설정하는 error-appender.xml 입니다. ERROR 레벨의 로그는 롤링 정책을 사용해서 파일로 저장하고 Slack으로 메세지도 전달해야합니다. 로그파일에 롤링정책을 저장하는 부분은 여타 레벨과 동일합니다. Slack으로 메세지를 전달하는 부분을 위주로 살펴보겠습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

<!-- error-appender.xml -->
<included>
    <!-- Slack 메세지 출력 설정부 -->
    <springProperty name="SLACK_WEBHOOK_URL" source="logging.slack.webhook.url" />
    <appender name="SLACK" class="com.github.maricn.logback.SlackAppender">
        <webhookUri>${SLACK_WEBHOOK_URL}</webhookUri>
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
${PID:-} --- [%15.15thread] %-40.40logger{36} %msg%n
[REQUEST_ID] : %X{REQUEST_ID:-NO REQUEST ID}%n
[REQUEST_METHOD] : %X{REQUEST_METHOD:-NO REQUEST METHOD}%n
[REQUEST_URI] : %X{REQUEST_URI:-NO REQUEST URI}%n
[REQUEST_TIME] : %d{yyyy-MM-dd HH:mm:ss.SSS}%n
[REQUEST_IP] : %X{REQUEST_IP:-NO REQUEST IP}%n
            </Pattern>
            <charset>utf8</charset>
        </layout>
        <colorCoding>true</colorCoding>
    </appender>

    <!-- 파일 롤링정책 Appender 정의 설정부 -->
    <appender name="FILE-ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>../logs/error/${DATE_PATTERN}.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] %-5level [%X{REQUEST_ID:-NO REQUEST ID}] ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n%n</pattern>
            <charset>utf8</charset>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>../logs/backup/error/%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>10</maxHistory>
            <totalSizeCap>1GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>
  • <springProperty name="SLACK_WEBHOOK_URL" source="logging.slack.webhook.url" />
    • application.properties나 application.yml에 설정되어 있는 내용을 가져와 변수로 사용할 수 있는 기능입니다. 저는 logging.slack.webhook.url에 Slack 웹 훅 주소를 설정해두었습니다.
      1
2
3
4
5

      # application.yml
logging:
  slack:
    webhook:
      url: <슬랙 웹 훅 주소>

      1
2

      # application.properties
logging.slack.webhook.url=<슬랙 웹 훅 주소>
    • 웹 훅 주소가 담긴 SLACK_WEBHOOK_URL 변수를 사용할 수 있게 됩니다.
  • <appender name="SLACK" class="com.github.maricn.logback.SlackAppender">
    • SLACK 이라는 이름의 Appender를 정의합니다.
    • logback-slack-appender 라이브러리를 프로젝트에 포함시키면 SlackAppender 클래스를 사용할 수 있습니다.
      1
2
3
4
5
6

      // build.gradle
dependencies {
    // ...
    implementation 'com.github.maricn:logback-slack-appender:1.6.1'
    // ...
}
  • <webhookUri>${SLACK_WEBHOOK_URL}</webhookUri>
    • 웹 훅 URI를 설정합니다.
    • 이전에 정의했던 변수인 SLACK_WEBHOOK_URL을 사용했습니다.
  • <layout class="ch.qos.logback.classic.PatternLayout">
    • 레이아웃을 지정합니다.
    • 여기서 사용된 REQUEST_ID, REQUEST_METHOD 변수는 MDC를 사용해서 컨텍스트 정보를 담은 것 입니다. 필터나 인터셉터를 사용해서 요청 컨텍스트 정보를 변수로 등록하면 로깅 설정 xml 파일에서 사용할 수 있습니다. (MDC 설정)

AsyncAppender 적용

Slack API 호출은 네트워크 작업, 즉 I/O 작업이기 때문에 시간이 걸릴 수 있다. 이런상황에서 동기식 Appender를 사용하면 로깅작업을 하는 동안 주 스레드를 차단하기 때문에 통신에 문제가 생기면 사용자 경험이 느려질 우려가 있다. AsyncAppender를 사용하면 작업이 별도의 스레드에서 비동기적으로 처리되어 애플리케이션의 주 실행흐름이 차단되지 않는다. 또 네트워크 지연이나 Slack 서비스에 문제가 생기더라도 애플리케이션의 응답성에 직접적인 영향을 주지 않는다. 또 AsyncAppender에 동기식 Appender를 래핑해 사용할 수 있다.

error-appender.xml에 다음 ASYNC_SLACK appender를 추가하였습니다.

1
2
3
4
5
6
7
8
9

<!-- Slack 메세지 비동기 출력 설정부 -->
<appender name="ASYNC_SLACK" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="SLACK" />
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>ERROR</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
</appender>
  • ch.qos.logback.classic.AsyncAppender를 사용하면
  • SLACK appender를 <appender-ref>태그를 사용해 비동기적으로 래핑하고 있다.
  • ch.qos.logback.classic.filter.ThresholdFilter를 필터로 사용하여 설정한 level 이상의 로그만 Slack으로 전송한다.

MDC 설정

error-appender.xml 파일에서 MDC를 이용해 요청 컨텍스트 정보를 아래와 같은 변수에 저장해 사용하였습니다.

  • REQUEST_ID
  • REQUEST_METHOD
  • REQUEST_URI
  • REQUEST_TIME
  • REQUEST_IP

MDC를 사용해서 어떻게 요청 컨텍스트 정보를 저장할 수 있는지 살펴보겠습니다.

요청 컨텍스트 정보를 담는 방법은 아주 간단합니다. 필터(Filter)나 인터셉터(Interceptor)를 정의해서 요청정보를 조회하고, MDC의 put 메서드를 호출해서 키(key)와 값(value)을 저장하면 됩니다. 저는 필터를 정의하였습니다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MdcLoggingFilter implements Filter {
    @Override
    public void doFilter(
        final ServletRequest request,
        final ServletResponse response,
        final FilterChain chain
    ) throws IOException, ServletException {
        setMdc((HttpServletRequest) request);
        chain.doFilter(request, response);
        MDC.clear();
    }

    private void setMdc(HttpServletRequest request) {
        MDC.put(REQUEST_ID.name(), UUID.randomUUID().toString());
        MDC.put(REQUEST_METHOD.name(), request.getMethod());
        MDC.put(REQUEST_URI.name(), request.getRequestURI());
        MDC.put(REQUEST_TIME.name(), LocalDateTime.now().toString());
        MDC.put(REQUEST_IP.name(), request.getRemoteAddr());
    }
}

MDC의 키로 사용되는 것들은 열거형으로 따로 정의하여 사용하였습니다..

1
2
3
4
5
6
7

public enum MdcKey {
    REQUEST_ID,
    REQUEST_METHOD,
    REQUEST_URI,
    REQUEST_TIME,
    REQUEST_IP
}

Filter 인터셉터를 통해 전달받은 ServletRequest에 담긴 정보를 MDC 에 키, 값 쌍으로 등록해주기만 하면 끝입니다. 요청이 끝난 후 MDC.clear() 메서드를 호출해서 더 이상 필요하지 않은 데이터를 삭제해주어야 한다는 점도 중요합니다. MDC 는 ThreadLocal을 사용하기 때문에 데이터를 삭제하지 않는다면 스레드가 재사용될 때 이전의 데이터가 남아 있을 가능성이 있기 때문입니다. 각 요청에 대한 로깅 컨텍스트를 깨끗하게 유지하기 위해서는 필수입니다.

출력 결과

Logback 설정이 잘 되었는지 확인하기 위해 루트 경로로 요청받았을 때 TRACE부터 ERROR레벨까지 로그를 출력하는 간단한 컨트롤러를 작성하였다.

1
2
3
4
5
6
7
8
9
10
11
12

@RestController
@Slf4j
public class FooController {
    @GetMapping("/")
    public void log() {
        log.trace("trace message");
        log.debug("debug message");
        log.info("info message");
        log.warn("warn message");
        log.error("error message");
    }
}

예상동작

  1. 콘솔에 각 로그들이 정상적으로 출력된다.
  2. INFO 로그는 프로젝트 폴더 기준 ../logs/info/{yyyy-MM-dd}.log 형식으로 기록된다.
  3. WARN 로그는 프로젝트 폴더 기준 ../logs/warn/{yyyy-MM-dd}.log 형식으로 기록된다.
  4. ERROR 로그는 프로젝트 폴더 기준 ../logs/error/{yyyy-MM-dd}.log 형식으로 기록된다.
  5. ERROR 로그는 Slack 에 메세지로 전송되며, 로그 메세지와 REQUEST_ID, REQUEST_METHOD 등의 정보를 보여준다.

콘솔 출력

파일 출력

Slack 메세지

ERROR 레벨의 로그가 Slack 메세지로 전달되는 것을 확인할 수 있다.

참고자료

개발, 로깅
메이플 주문서 시뮬레이터
This post is licensed under CC BY 4.0 by the author.