SpringBoot Logging 설정

사내에서 배포 시 nohup 으로 application을 띄우고 로그에 logrotate 하는 것을
서비스 등록하고 logback 설정을 통해 rotate 할 수 있도록 변경하는 과정에서 알게된 내용이다.

Logback

Springboot 는 "starters" 사용 시 기본적으로 logback을 사용한다.
기본 설정은 console 에 log 를 찍는다. 운영 로그를 보기 위해선 파일로 남기는 것이 좋고, 적절한 rolling 정책을 지정해주는 것이 좋다.

application.yml 파일 또는 logback 설정 xml 파일을 직접 만들어 로그 관련 설정을 할 수 있다.
세부 설정을 하기 위해 xml 파일을 통해 만들자.
(application.yml 설정을 사용하는 경우 문서를 참조하자)

logback을 사용하므로, resources/ 하위에 logback-spring.xml 파일을 생성하자.
이 파일에서부턴 logback 의 설정을 사용하므로, logback 관련 메뉴얼을 확인해서 만들면 된다.

생성한 설정 파일은 아래와 같다.

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <property name="LOG_DIR" value="/home/kangsan/test/logs"/>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern> %d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) %magenta(%-4relative) --- [ %thread{10} ] %cyan(%logger{20}) : %msg%n </pattern>
    </encoder>
  </appender>
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/vpki.current.log</file>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %-4relative --- [ %thread{10} ] %logger{35} - %msg%n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>${LOG_DIR}/vpki.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
      <maxHistory>365</maxHistory>
    </rollingPolicy>
  </appender>
  <logger name="org.springframework" level="info"/>
  <logger name="org.hibernate" level="info"/>
  <root level="info">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

옵션에 대한 간략한 설명

• $ java -DLOG_DIR=/var/log/application com.baeldung.logback.LogbackTests 이런식으로 Property 값을 채워서 줄 수 있다.
• 혹시나 해서.. file명의 'vpki' 는 application 이름이다.
• configuration은 appender, logger, root 로 구성된다.
• appender: 실제 로깅을 수행하는 녀석
  • ConsoleAppender: 콘솔에 찍어주는 녀석
  • RollingFileAppender: File로 써주면서 Rolling(주기적으로 로그를 분리해서 처리) 도 해주는 녀석
    • rollingPolicy: rolling 정책 (TimeBased - 시간기준, SizeAndTimeBased - 시간 및 로그파일 크기 기준)
    • fileNamePattern:
      • 설정한 fileNamePattern을 통해 롤오버 주기를 계산하고, 각 아카이브 파일 이름을 만듦
      • TimeBased 일땐 %d(날짜)가, SizeAndTimeBased 일땐 %d, %i(순서) 가 필수이다.
      • 파일명의 확장자가 (.gz) 이면 아카이브의 자동 압축도 지원한다.
    • maxHistory: 보관기간 제한
      • maxHistory의 기준은 fileNamePattern의 값으로부터 추론(inferred) 됨
      • fileNamePattern에 %d{yyyy-MM-dd} 로 적힌 경우 rollover의 기준이 하루이므로 maxHistory 365는 365일을 의미
  • rollover 는 시간 기준으로 정확히 돌아가지 않는다. 이벤트가 도착한 기준으로 rollover 가 수행된다. (아래에서 설명)
  • 자세한건 http://logback.qos.ch/manual/appenders.html
• logger: package 별 logger 구성
  • logger 의 level
    
  • 위에서 아래로 보는거다... 왼쪽에서 오른쪽으로 봐서 거꾸로 이해했었다...
  • Trace면 모든 로그를, Error면 Error로그만!
• root: root 로거 구성
  -<appender-ref> 를 통해 위에서 정의한 appender 를 달아준다.

Rollover의 동작 방식에 대하여

For various technical reasons, rollovers are not clock-driven but depend on the arrival of logging events. For example, on 8th of March 2002, assuming the fileNamePattern is set to yyyy-MM-dd (daily rollover), the arrival of the first event after midnight will trigger a rollover. If there are no logging events during, say 23 minutes and 47 seconds after midnight, then rollover will actually occur at 00:23'47 AM on March 9th and not at 0:00 AM. Thus, depending on the arrival rate of events, rollovers might be triggered with some latency. However, regardless of the delay, the rollover algorithm is known to be correct, in the sense that all logging events generated during a certain period will be output in the correct file delimiting that period.

rollover 는 logging 이벤트 도착 기준으로 동작한다. 그래서 시간 기준으로 rolling을 한다해도 정확히 그 시간에 rolling이 일어나지 않을 수 있다.

1분마다 rolling하도록 설정 후 테스트 해서 동작 방식을 확인하였다.

1. 11분부터 14분까지 로그 이벤트를 발생시키고, 5분 후 19분에 이벤트 발생시키니 15분 아카이브가 생성됨.
   

2. 1분 후 20분에 로그 이벤트를 발생시키니 19분 아카이브가 생성됨

즉 1분마다 rolling 정책을 설정했어도, 로그 이벤트가 없다면 따로 아카이브 하지 않는다는것과 아카이브 시점은 시간 기준이 아닌 로그 이벤트가 발생된 순간에 trigger 됨을 알 수 있었다.

참고
https://www.baeldung.com/logback
https://meetup.toast.com/posts/149