Log Back 적용기

프로젝트에 기능 구현을 제대로 하기전에 LogBack 관련 세팅을 먼저 하는게 좋을 것 같다는 피드백을 받았다. 그 이유를 생각해봤는데 프로젝트를 개발함에 있어서 log를 확인하고, 관리하는 것에 대한 장점을 최대한 누릴 수 있다고 생각했다.

그리고 log를 관리하는 것에 대한 장점이 무엇인지, 이런 log 관리를 어떻게 하는지, Log Back이란 무었인지 알아보았다.

Log Back? Slf4j?

프로젝트를 시작하기전에 스프링을 공부하면서 slf4j를 종종 사용한 경험이 있다. 로그를 찍는 용도로 사용한다고만 알고 있었기에 , Log Back 과 Slf4j의 관계를 잘 모르고 있었다.

알아본바로는 Sl4fj(Simple Logging Facade for Java)는 Facade 패턴으로 , 구현체의 종류와 상관없이 일관된 로깅 코드를 작성 할 수 있다. 그리고 이런 Slf4j의 구현체가 LogBack이다. Slf4j의 구현체는 LogBack 말고 log4j 등이 있다.
LogBack은 SpringBoot의 기본 Logging framework로 사용되고 있다.

퍼사드 패턴 - 위키백과, 우리 모두의 백과사전

출처 : https://docs.spring.io/spring-boot/docs/2.3.1.RELEASE/reference/html/spring-boot-features.html#boot-features-logging

요약

요약하자면 slf4j는 퍼사드 패턴을 통해 로깅을 해주는 것이고, 이를 구현한 LogBack, Log4j등이 있다.

스프링에서는 LogBack을 slf4j의 기본 구현체로 사용한다.

---

LogBack 적용해보기

일단 Log 관리를 하기 위해서 자료를 더 찾아 보았는데, log를 설정하는 방식은 크게 2가지가 있다.

1. 스프링 부트에서 지원하는 기능으로 LogBack을 설정
2. 로깅 기능을 xml 파일로 커스터마아징 해서 사용

난 2번을 사용하기로 했다.

1번을 이용하면 기본적으로 지원하는 Log Format 사용, Console Output, File Output, Log Level 지정 등을 할 수 있다. 하지만 이를 커스텀으로 사용한다면 로그를 세밀하게 관리를 해줄 수있고, xml 파일은 아직 까지 다뤄본적이 없어서 이번에 한번 다뤄보고 싶다는 생각을 했다. 무었보다 세밀한 세팅이 가능하다고 한다.

Spring Boot Features

LogBack 구성 파일 문법

configuration 태그는 내부에 최대 1개의 root 태그를 갖고, 0개 혹은 여러개의 appender와 logger를 가진다.

logger

• Logger는 <logger> 태그로 구성된다.
• level 속성을 지정 할 수가 있는데, 일반적으로 level은 대소문자를 구분하지 않고 TRACE, DEBUG,INFO, WARN , ERROR, ALL 혹은 OFF 가 있다.
• 특이한 경우로 대소문자를 구분하지 않는 특수 값인 INHERITED, 혹은 동의어 NULL은 상위 로거의 level을 따른다.

root

• root 는 태크를 통하여 구성된다. 루트 로거의 속성은 단 하나의 level 속성만 허용된다.
• 루트 로거의 이름은 이미 ROOT로 정해져 있기에 name 속성도 포함하지 않는다.
• level 속성은 logger 와 동일하게 가져갈 수 있지만, INHERITED 와 NULL은 가질 수가 없다. → root가 최상단 로거이기 때문에

<configuration>

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

  <logger name="chapters.configuration" level="INFO" />
	<logger name="chapters.configuration.Foo" level="DEBUG"/>

  <!-- turn OFF all logging (children can override) -->
  <root level="OFF">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

위의 예제 코드를 살펴보자! xml 파일이다.

루트 로거 레벨이 OFF로 설정되어 있기 떄문에 아무런 로거를 출력하지 않는다. 하지만 하위에 있는 로거[ chapters.configuration ] 이 INFO 레벨로 설정되어 있기 때문에 [ chapters.configuration ] 하위에 있는 로거들은 INFO 레벨로 지정이 된다.

[ chapters.configuration.Foo ] 는 level이 DEBUG 로 지정되어 있기 때문에. [ chapters.configuration.foo ] 의 하위 level에 있는 로거들은 모두 DEBUG 를 갖게된다.

그럼 상단에 있는 appender 는 무엇일까?

Appender

Appender는 태그를 통하여 구성 된다. name와 class 속성을 필수적으로 가진다.

• name : appender의 이름을 명시
• class : 인스턴스화 시킬 appender 클래스를 명시
  인스턴스화 시킬 수 있는 class 종류 :
  - ch.qos.logback.core.ConsoleAppender : 콘솔에 로그를 기록
  - ch.qos.logback.core.FileAppender : 파일에 로그를 기록
  - ch.qos.logback.core.rolling.RollingFileAppender : 여러개의 파일을 순회하면서 로그를 기록
  - ch.qos.logback.classic.net.SMTPAppender : 로그를 메일로 전송
  - ch.qos.logback.classic.db.DBAppender : 데이터베이스에 로그를 기록
• 태그는 0개 혹은 1개의 태그와 태그를 가질 수 있다.

<configuration>

  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>myApp.log</file>

    <encoder>
      <pattern>%date %level [%thread] %logger{10} [%file:%line] %msg%n</pattern>
    </encoder>
  </appender>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="FILE" />
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

위 예제 파일을 확인해보자.

FILE 와 STDOUT 라는 appender가 있다.

FILE appender 는 “ch.qos.logback.core.FileAppender” 라는 파일 appender를 인스턴스화 하고 있고,

STDOUT appender 는 “ch.qos.logback.core.ConsoleAppender” 라는 콘솔 appenmder를 인스턴스화 하고 있다.

FILE 은 지정된 pattern 맞춰 파일에 로그를 기록한다. STDOUT 도 동일하게 지정된 pattern 에 맞춰서 콘솔에 출력을 한다.

이 두개의 appender는 를 통해 rootlogger에 등록이된다.

패턴 알아보기

%d : 로그 기록시간
%thread : 현재 Thread 이름

%-5level : 로그 레벨, -5는 출력의 고정폭 (5글자)

%logger{35} : 축약된 logger name, 35는 최대 자릿수

%msg : 로그메시지

%n : 줄바꿈

${PID:-} : 프로세스 아이디

%p : 로깅 레벨

%F : 로깅이 발생한 프로그램 파일명

%M : 로깅일 발생한 메소드의 이름

%l : 로깅이 발생한 호출지의 정보

%L : 로깅이 발생한 호출지의 라인 수

%t : 쓰레드 명

%c : 로깅이 발생한 카테고리

%C : 로깅이 발생한 클래스 명

%m : 로그 메시지

%r : 애플리케이션 시작 이후부터 로깅이 발생한 시점까지의 시간

---

이제 진짜로 로그를 지정해보자

우선 FILE 방식과 Console 방식을 혼용해서 쓰기로 했다.

일정 레벨 이상에 대한 로그는 FILE 방식으로 따로 저장해두는게 맞다고 생각했다.

또한 아직 개발 단계이기 때문에 개발 단계 레벨에서 쓰이는 레벨에 대한 로그는 콘솔 출력으로 해야겠다고 생각했다.

정리하자면

- info 레벨 이상은 콘솔 출력 + 파일 저장 
- 프로젝트 하위 레벨(src/~) 에서 발생하는 에러는 debug 레벨 기준으로 콘솔 출력

으로 logback 을 커스터 마이징 하기로 했다.

우선 LogBack을 커스터마이징 할 파일을 생성해줘야한다. 스프링 부트에서는 Log 커스터마이징 파일에는 suffix로 -spring 가오는 xml 파일을 사용하는 것을 권장한다.

Spring Boot Features

---

우선 로그를 콘솔에 출력하는 appender 와 파일로 저장하는 appender를 만들어보자!

로그 - 콘솔

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{36} - %msg%n</Pattern>
        </layout>
</appender>

위의 코드는 로그를 콘솔에 출력하기 위한 appender 설정 코드이다.

ConsoleAppender 를 인스턴스로 가지고, 이름이 STDOUT 이라는 appender 를 생성했다.

이 이때 로그의 패턴은 으로 만들어 준다.
년-월-일-시간-초 - 쓰레드 - 로그레벨 - 에러 출력 사항 이 출력되도록 설정했다.

로그 - 파일 저장

<appender name="INFO_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./logs/info.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./was-logs/info.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>100</maxHistory>
	        </rollingPolicy>
    </appender>

단순 출력 로그보다 태그가 많아 보인다. 하나씩 파헤쳐 보자.

최상단 코드를 확인해보면 INFO_LOG_FILE 이라는 이름을 가지고, RollingFileAppender 라는 인스턴스를 가진 appender 를 생성한다는 것을 알 수 있다.

<file> 생성한 로그 파일 저장 경로를 지정해준다.

<pattern> 위에서 생성한 콘솔 출력 패턴과 동일하다.

<rollingPolicy> 롤링 정책을 지정하는 것이다. TimeBasedRollingPolicy 인스턴스를 사용한다.

• TimeBasedRollingPolicy 은 하루에 한번, 일주일에 한번, 1달에 한번 롤링 정책을 적용할 수 있도록 해준다. → 해당 정책 지정 태그
• <fileNamePattern> 을 보면 패턴 내에 yyyy-MM-dd 형태가 있는 것을 볼 수 있다. 이는 롤 오버라 하는데, yyyy-MM-dd 처럼 날짜 단위로 지정이 되어 있으면 per day, 즉 하루에 한번 로깅파일을 생성한다는 것이다.

만약 yyyy-MM 형태라면 롤 오버가 달에 한번으로 지정이된다.

• <maxFileSize> 로그구성파일의 크키가 너무 커지는 것을 방지하기 위한 옵션이다. 최대 용량을 10MB로 설정 해주었다. KB , MB, GB 등 설정 가능
• <maxHistory> 일자별 백업파일의 보관 기간을 얼마로 정할 것인지 대한 옵션
  100일 치의 로그 파일을 저장하도록 설정했다.

이제 생성한 appender를 로그로 등록 해보자

Root

로그 등록 방식에는 크게 두가지가 있는데 root 방식과 logger 방식이있다.

우선 root 방식을 사용해보자.

- info 레벨 이상은 콘솔 출력 + 파일 저장 

다음의 요구사항에 맞는 root 로거를 설정해보자.

위에서 만든 2개의 appender를 사용해서 info 레벨을 기준으로 로그를 출력 및 저장하도록 root 로거를 생성해보자.

<root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="INFO_LOG_FILE"/>
</root>

root 로거는 <root> 태그로 지정할 수 있다. 이때 level을 INFO 로 설정 해주었다. 즉 INFO 를 포함한 상위 레벨(WARN, ERROR 에 대한 예외 로그를 root에서 처리를 할 수 있다.

해당 root 로거에서 사용하는 appender은 appender-ref로 참조할 수 있다.

logger

이제 logger 방식을 사용해보자, 특정 범위를 지정하여 로그를 세팅 할 수가 있다.

logger 를 사용하면 다음의 요구 사항을 실행 할 수 있다.

- 프로젝트 하위 레벨(src/~) 에서 발생하는 에러는 debug 레벨 기준으로 콘솔 출력

<logger name="hamkke.board" level="DEBUG" appender-ref="STDOUT"/>

내 프로젝트 ( hankke.board) 를 기준으로 하위레벨에서 생성되는 Debug 이상 로그를 콘솔 출력으로 나타 낼 수 있도록 설정 했다.

현재 logback-spring.xml 상태

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOGS_ABSOLUTE_PATH" value="./logs"/>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{36} - %msg%n</Pattern>
        </layout>
    </appender>

    <appender name="INFO_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./logs/info.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>./was-logs/info.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>100</maxHistory>
        </rollingPolicy>
    </appender>

    <logger name="hamkke.board" level="DEBUG" appender-ref="STDOUT"/>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="INFO_LOG_FILE"/>
    </root>
</configuration>

---

AsyncAppender

출처 : LogBack 공식 문서

Chapter 4: Appenders

AsyncAppender 는 로깅 이벤트를 비동기적으로 기록을 한다. 이때, 작업을 수행하기 위해서는 다른 어펜더를 참조해서 사용해야한다.

AsyncAppender의 특징

1. 로깅 이벤트 관리 전략 - 블로킹 큐 용량을 80% 기준으로 이벤트 처리

• AsyncAppender에 의해 생선된 worker thread는 큐[Blocking Queue]로부터 이벤트를 가져와서 AsyncAppender에 참조 된 단일 어펜더에 전달한다.
  • Blocking Queue : 특정 상황(큐가 꽉 찼을 때, 원소를 넣거나, 큐가 비어있을 때 원소를 빼는 경우)에 쓰레드를 대기하도록 하는 큐이다. → 생성된 로깅 이벤드들을 블로킹 큐에 적재해 비동기로 처리함
• 만약 Blocking Queue의 용량이 80%가 넘어간다면 TRACE, DEBUG, INFO 레벨의 로그 이벤트는 drop 된다. → 아마 큐가 꽉차게 되는 경우 쓰레드가 대기 상태로 변하기 때문에,퍼포먼스가 하락 될 수 있기 때문
• 이러한 전략은 로깅 이벤트가 손실 되더라도, 로깅의 퍼포먼스가 향상된다.
  → 서비스에서 치명적인 영향을 끼칠 수 있는 로그레벨을 수집을 우선으로하면서 로깅의 퍼포먼스를 향상 시킴

---

2. 어플리케이션의 정지와 배포

• 어플리케이션이 종료되거나 배포시, AsyncAppender 는 작업중인 쓰레드를 중지 및 회수하고 큐에서 로깅 이벤트를 플러시하기 위해 AsyncAppender 를 중지해야한다. 모든 Appender 를 멈춰야 AsyncAppender 가 멈춘다.
• 이때 AsyncAppender 는 worker 쓰레드가 maxFlushTime 에 지정된 제한 시간까지 플러시 될 때까지 기다린다. 이때 로거 컨텍스트가 닫치는 동안 누락되는 로깅 이벤트들이 있다면 maxFlushTime 설정으로 타임아웃 시간을 늘려줘야한다.
• 특이 사항으로 maxFlushTime 을 0 으로 설정하면 대기중인 모든 로깅 이벤트가 플러시 될 때 까지 기다리도록 한다.

요약 : 어플리케이션이 종료 되거나 배포시 AsyncAppender 는 작업중인 모든 어펜더와 워커 쓰레드를 중지해야한다. 이때, 처리 되던 작업들이 누락 될 경우 타임아웃 설정 maxFlushTime 을 늘려줘야한다.

만약 maxFlushTime을 0으로 지정하면 모든 작업을 처리 할 때 까지 기다린다.

3. 종료 후 정리

JVM의 종료 모드에 따라서 대기열에 있는 이벤트를 처리하는 worker 쓰레드가 중단되어 로깅 이벤트 처리가 꼬일 수 있다. 이런 상황은 일반적으로 LoggerContext가 완전히 중지되지 않거나 JVM이 일반적인 제어 흐름이 아니라 외부에서 종료 될 때 발생한다. 이런 조건에서 worker 쓰레드가 중단되는 것을 방지하기 위해, LoggerContext를 올바르게 중지하는 shutDown 훅을 jvm런타임에 삽입할 수 있다.
shutdown 훅은 다른 종료 후크가 이벤트를 기록하려고 할 때, LogBack을 완전히 종료하기 위해 선호되는 방법이다.

shutDown 훅 설정 방법

<configuration debug="true">
   <!-- in the absence of the class attribute, assume
   ch.qos.logback.core.hook.DefaultShutdownHook -->
   <shutdownHook/>

   <!-- rest of the config file.. -->

</configuration>

---

AsyncAppender 적용 후 로깅 설정 상태

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <property name="LOGS_ABSOLUTE_PATH" value="./logs"/>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <layout class="ch.qos.logback.classic.PatternLayout">
          <Pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{36} - %msg%n</Pattern>
      </layout>
  </appender>

  <appender name="INFO_LOG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>./logs/info.log</file>
      <filter class="ch.qos.logback.classic.filter.LevelFilter">
          <level>INFO</level>
      </filter>
      <encoder>
          <pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{35} - %msg%n</pattern>
      </encoder>
      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
          <fileNamePattern>./was-logs/info.%d{yyyy-MM-dd}.%i.log.zip</fileNamePattern>
          <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
              <maxFileSize>10MB</maxFileSize>
          </timeBasedFileNamingAndTriggeringPolicy>
          <maxHistory>100</maxHistory>
      </rollingPolicy>
  </appender>

  <springProfile name="local">
      <appender name="ASYNC_STDOUT" class="ch.qos.logback.classic.AsyncAppender">
          <queueSize>10000</queueSize>
          <maxFlushTime>0</maxFlushTime>
<appender-ref ref="STDOUT"/>
      </appender>
      <logger name="hamkke.board" level="DEBUG" appender-ref="STDOUT"/>

      <root level="INFO">
          <appender-ref ref="ASYNC_STDOUT"/>
      </root>
  </springProfile>

  <springProfile name ="ci">
      <appender name="ASYNC_INFO_LOG_FILE" class="ch.qos.logback.classic.AsyncAppender">
          <maxFlushTime>0</maxFlushTime>
          <appender-ref ref="INFO_LOG_FILE"/>
      </appender>
      <root level="WARN">
          <appender-ref ref="ASYNC_INFO_LOG_FILE"/>
      </root>
  </springProfile>
</configuration>