logback-spring.xml으로 파일 로그 남기기

출처: https://loosie.tistory.com/829

스프링 부트에서 Logback 사용하기

스프링 부트에선 기본적으로 Logback이 설정되어 있다. 다음과 같이 SLF4J의 3가지 모듈이 이어져 Logback과 연결된다. 다음과 같이 spring-boot-starter-logging 라이브러리에 기본적으로 설치되어 있다.

Controller에 로그 API를 작성하여 기본적으로 로깅이 뭔지 모두 호출해보자.

/**
 * trace < debug < info < warn < error
 * default : info
 */
@RestController
public class FooController {
	private final Logger log = LoggerFactory.getLogger(this.getClass().getSimpleName());

	@GetMapping("/")
	public void log(){
		log.trace("trace message");
		log.debug("debug message");
		log.info("info message"); // default
		log.warn("warn message");
		log.error("error message");
	}
}

// spring-boot-starter-web 의존성을 추가했다면 @Slf4j 애노테이션으로 바로 log 사용이 가능하다.
@RestController
@Slf4j
public class FooController {
	@GetMapping("/")
	public void log(){
		log.trace("trace message");
		log.debug("debug message");
		log.info("info message"); // default
		log.warn("warn message");
		log.error("error message");
	}
}

다음과 같이 콘솔창에서 로그가 기록되는 것을 볼 수 있다. 그런데 몇 개의 로그는 보이지 않는다. 그 이유는 로그 레벨은 기본적으로 [trace > debug > info > warn > error] 순이며 디폴트 설정이 info로 되어있기 때문에 trace와 debug 로그는 기록되지 않은 것이다.

info까지만 호출

1. logback-spring.xml으로 콘솔에 로그 출력하기

처음에 언급했던 바와 같이 로깅을 하면 앱 개발시 운영 중 발생하는 문제점을 모니터링하거나 추적하는 데 용이하고 데이터를 분석해 통계를 낼 수도 있다. 따라서 로그 레벨을 조절하여 콘솔에 출력하고 이를 기록하는 데에는 그만한 주어진 목적이 있다고 보면 된다. 콘솔 로그 수준을 변경하는 가장 간단한 방법은 application.yml이나 application.properties로 설정해주는 것이다.

// application.yml
logging:
  level:
    root: debug

debug 레벨에서 출력

yml 설정은 스프링 부트 위에서만 가능한 추상화된 방식이기 때문에 이를 사용하려면 문서에서 제공하는 xml로 설정하는 방식을 익혀야 한다. 그리고 사실상 로그 설정 분리만 따로 하기 위해서 xml을 사용하여 설정하는 것이 더 세세한 커스텀에 대한 자료도 많아 개인적으로 더 좋아보인다.  xml 설정을 하기 위해서는 logback-spring.xml 파일을 생성하여 직접 커스텀을 해줘야 한다. xml 설정에서 주요 컴포넌트로는 appender와 logger 두 가지로 나눌 수 있다.

• appender: logger를 어디에 출력할지 설정한다. 콘솔, 파일, DB 등 지정할 수 있다.
• logger: 아래 예제는 매우 단순한 형태로 실제 업무에선 FILE 뿐만 아니라 SockerAppender나 LogStash 등도 함께 설정해서 사용할 수 있다.

다음 xml 설정은 콘솔에는 모든 로그를 debug 수준의 로그만 출력되도록 설정한 것으로 위 application.yml 설정과 동일하다. 그리고 log를 가독성있게 출력하기 위해서는 포맷을 일관성있게 설정해주었다.

• %20logger: 왼쪽 공백(오른쪽 정렬), 최소 길이 20, 최대 길이 x
• %-20logger: 왼쪽 공백 x(왼쪽 정렬), 최소 길이 20, 최대 길이 x
• %20.30logger: 왼쪽 공백 x(왼쪽 정렬), 최소 길이 20, 최대 길이 30

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<!-- 콘솔(STDOUT)에 log 기록 -->
    <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] %-5level ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n</Pattern>
        </layout>
    </appender>

<!-- log root 레벨 설정 (logging.level.root=info)-->
    <root level="debug">
<!--     참조할 appender 설정 - STDOUT -->
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

최대한 스프링 부트에서 기본적으로 제공하는 logback 포맷이랑 일치하여 커스텀해줬지만 아직 아쉬운 게 하나있다. 모든 로그가 흑백이라 줄바뀜이나 로그 레벨 분류가 힘들어 가독성이 떨어진다.

logback.xml 설정한 로그로 출력

2. 콘솔 로그에 색상 입히기

로그에 색상을 입히는 것은 설정을 통해서 간단하게 적용할 수 있다. 공식 홈페이지에 자세히 나와있다.

• %clr(pattern){color}: 로그 pattern을 %clr ~ {color}로 감싸주면 된다.
• springboot에서 제공하는 콘솔 로그 패턴 색상이랑 똑같이 설정해주었다. [org.springframework.boot.logging.logback 패키지> deafults.xml 파일 참고]

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 로그 패턴에 색상 적용 %clr(pattern){color} -->
    <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />

    <!-- log 변수 값 설정 -->
    <property name="CONSOLE_LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-3relative]  %clr(%-5level) %clr(${PID:-}){magenta} %clr(---){faint} %clr([%15.15thread]){faint} %clr(%-40.40logger{36}){cyan} %clr(:){faint} %msg%n"/>

    <!-- 콘솔(STDOUT) -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>${CONSOLE_LOG_PATTERN}</Pattern>
        </layout>
    </appender>

</configuration>

다음과 같이 색상이 들어가 이제는 콘솔에 가독성있는 로그가 출력되는 것을 확인할 수 있다.

색상입힌 로그 출력

3. 콘솔과 파일에 로그 따로 기록하기

RollingFileAppender

콘솔에만 로깅하는 것이 아닌 파일에도 따로 로깅을 기록하고 싶을 때 사용하는 appender는 FileAppender이다.

RollingFileAppender는 FileAppender를 상속하여 로그 파일을 rollover한다. rollover는 다음 파일로 이동하는 행위로 한 로그 파일에 무한정 기록할 수 없으니 특정 기준에 따라 기록하는 파일 대상을 바꿔주는 것이다. 해당 appender는 주요 2가지 설정을 해줘야 한다.

• RollingPolicy: rollover에 필요한 action을 설정한다. (ex. TimeBasedPolicy, SizeAndTimeBasedRollingPolicy 등)
• TriggeringPolicy: rollover가 발생하는 기준(정책)을 설정한다.

TimeBasedPolicy와 SizeAndTimeBasedRollingPolicy

TimeBasedPolicy는 시간을 기준으로 rollover를 설정할 수 있다면, SizeAndTimeBasedRollingPolicy 시간에다가 파일 크기까지 고려하여 rollover를 설정할 수 있다.

• fileNamePattern: 아카이브 될 로그 파일의 패턴을 정의한다. %d 문자를 이용해 파일의 적절한 부분을 dateTime 패턴으로 바꿔준다. default(%d)는 yyyy-mm-dd로 매일 자정 새로운 로그 파일로 rollover 한다.
• maxHistory: 아카이브에 저장할 로그 파일 개수를 지정한다. fileNamePattern에 명시된 dateTime 패턴의 최소 단위에 따라 rollover 단위가 달라진다.
• totalSizeCap: 로그 파일 아카이브 저장소 최대 크기를 지정한다. 이를 초과하면 가장 오래된 파일이 삭제된다.
• cleanHistoryOnStart: true로 설정하면 앱을 시작하면 아카이브된 로그 파일을 모두 삭제한다. default는 false이다.

spring-logback.xml 파일 설정

다음 xml 파일은 콘솔에 모든 로그를 info 수준에서 출력해주고 '/logs/loback.log' 파일에 springframework.web 로그를 debug 수준으로 기록한다. 그리고 rollover 정책은 파일 크기와 시간(SizeAndTimeBased)을 기준으로 설정되어 있다.

• fileNamePattern: yyyy-mm-dd로 일 단위로 로그를 기록한다.
• Size: 로그 파일 아카이브 저장소는 최대 3GB로 이를 초과한다면 가장 오래된 파일이 삭제된다.
• Time: 최대 30일의 히스토리가 남는다. 30일 이상의 파일이 기록될시 가장 오래된 파일이 삭제된다.

그리고 3번에서 콘솔 로그는 색상을 입혀 출력하였지만 FILE에서 출력되는 로그는 색상을 입히는 문자를 빼줘야 한다. 이는 property로 각 패턴을 따로 정의해주면 더 사용하기 편리하다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- log 기록 절대 위치 설정 -->
    <property name="LOGS_ABSOLUTE_PATH" value="./logs" />

    <property name="CONSOLE_LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-3relative]  %clr(%-5level) %clr(${PID:-}){magenta} %clr(---){faint} %clr([%15.15thread]){faint} %clr(%-40.40logger{36}){cyan} %clr(:){faint} %msg%n"/>
    <property name="FILE_LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %-5level ${PID:-} --- [%15.15thread] %-40.40logger{36} : %msg%n"/>

    <!-- 콘솔(STDOUT) -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>${CONSOLE_LOG_PATTERN}</Pattern>
        </layout>
    </appender>

    <!-- 파일(FILE) -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <!--     log 기록할 파일 위치 설정 -->
        <file>${LOGS_ABSOLUTE_PATH}/logback.log</file>
        <!--     log 기록 타입 인코딩 -->
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover -->
            <fileNamePattern>logFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <!-- keep 30 days' worth of history capped at 3GB total size -->
            <maxHistory>30</maxHistory>
            <totalSizeCap>3GB</totalSizeCap>
        </rollingPolicy>
    </appender>

    <!-- log 레벨 설정 (logging.level.root=info)-->
    <root level="info">
        <!--     참조할 appender 설정 - STDOUT -->
        <appender-ref ref="STDOUT" />
    </root>

    <!-- log 레벨 설정 (org.springframework.web=debug)-->
    <logger name="org.springframework.web" level="debug">
        <appender-ref ref="FILE" />
    </logger>

</configuration>

해당 로그를 설정하면 아래와 같은 결과를 콘솔과 파일을 통해서 확인할 수 있다.

콘솔에 출력되는 로그

파일에 기록되는 로그

4. Spring 앱 Profile에 따라 로그 기록하기

실수로 다른 환경에 로그 기록이 덮어씌워지거나 갱신되는 일을 방지하고자 프로젝트 운영시 각 실행 환경에 따라 로그 전략을 다르게 설정해줘야 한다. sping에서 실행된 profile에 따라 조건들을 xml에서 설정할 수 있다.

• local: 로컬 환경. 콘솔에 info 수준의 로그를 기록한다.
• dev: 개발 환경. 콘솔에 debug 수준의 로그를 기록하고 로컬에서 테스트 용으로 file에 org.springframework.web 로그를 debug 수준으로 기록한다.
• real: 배포 환경: 콘솔에 info 수준의 로그를 기록하고 file에 org.springframework.web 로그를 debug 수준으로 기록한다.

dev환경과 real환경에서 사용되는 로그 설정 값들을 다음과 같이 작성하였다.

// application-dev-log.yml
log:
  config:
    path: ./logs
    filename: app-dev
    maxHistory: 7 # 7일
    totalSizeCap: 10MB # 로그 파일 사이즈

// application-real-log.yml
log:
  config:
    path: ./logs
    filename: app-release
    maxHistory: 30 # 30일
    totalSizeCap: 1GB # 로그 파일 사이즈

최종적으로 작성된 xml 파일은 다음과 같다. 스프링 앱 실행 환경에 따라 읽어오는 설정 값도 다르게 받도록 설정해줘야 한다.

• 각 환경마다 다르게 설정한 값들을 <springProfile name="{profile}"> ~ </springProfile>로 불러온다.
• 그리고 <springProperty name="{변수 이름}" source="yml 변수 이름"/>를 사용하여 값을 설정해준다.

    
    

    
        
    
    
        
    

    
    
    
    
    

    
    

    
    
        
            ${CONSOLE_LOG_PATTERN}
        
    

    
    
        
        ${LOG_PATH}/${LOG_FILE_NAME}.log
        
        
            ${FILE_LOG_PATTERN}
        
        
            
            ${LOG_PATH}/${LOG_FILE_NAME}.%d{yyyy-MM-dd}.log
            ${LOG_MAX_HISTORY}
            ${LOG_TOTAL_SIZE_CAP}
        
    

    
    
    
        
            
            
        
    
    
    
        
            
            
        
        
            
            
        
    
    
    
        
            
            
        
        
            
            
        
    

각 환경 별로 실행하였을 때 생성되는 로그 파일로 서로 다른 설정 값이 불러와지는 것을 확인할 수 있다.

각 환경마다 생성된 로그 파일

AsyncAppender로 로깅 비동기 처리하기

AsyncAppender는 로깅 이벤트를 비동기적으로 처리한다. 이벤트 디스패처로만 작동하므로 작업을 수행하기 위해서는 다른 Appender를 참조해야 한다.

속성 타입 설명

queueSize	int	블로킹 큐의 최대 용량이다. 기본적인 큐 사이즈는 256이다.
discardingThreshold	int	기본적으로 블로킹 큐에 20% 용량이 남아있으면 TRACE, DEBUG, INFO 수준의 이벤트를 삭제하고 WARN 및 ERROR 수준의 이벤트만 유지한다. 모든 이벤트를 유지하려면 해당 값을 0으로 설정해줘야 한다.
includeCallerData	boolean	caller 데이터를 추출하는 것은 다소 비용이 많이 들 수 있다. 성능 향상을 위해 기본적으로 이벤트가 이벤트 대기열에 추가될 때 이벤트와 연결된 caller 데이터는 추출하지 않는다.includeCallerData 속성을 true로 설정하여 이 Appender에 호출자에 caller 데이터를 포함하도록 지시할 수 있다.(true로 하면 로그를 남길 때 현재 클래스에 어느 라인에서 기록되는지 알수 있게 된다.)
maxFlushTime	int	LoggerContext가 중지되면 AsyncAppender stop 메서드는 작업자 스레드가 완료될 때까지 제한시간을 기다린다. maxFlushTime을 사용하여 최대 queue flush timeout을 ms단위로 정한다.  그래서 서버가 멈추거나 재배포될 때는 maxFlushTime만큼 큐에 남아있던 걸 처리하고 끝난다. 0으로 설정하면 queue를 모두 처리할 때까지 기다린다.
neverBlock	boolean	false로 설정하면 큐가 다 찰 경우 block 상태로 전환하여 메세지를 보존한다. true로 설정하면 큐가 다 찰 경우 block하지 않고 메세지를 삭제하기 때문에 속도가 빨라진다.

기본 Appender vs AsyncAppender 성능 비교하기

기본 Appender를 사용하는 것과 AsyncAppender 기능을 입혀서 사용하는 것과의 성능을 비교하기 위해서 로그 1만개를 출력하는 로직을 작성해봤다.

@Service
@Slf4j
public class FooService {
	/**
	 * trace < debug < info < warn < error
	 * default : info
	 */
	public void log(){
		for(int i=0; i<10_000; i++){
			log.info("info message"+i); // default
		}
	}
}

다음과 같이 AsyncAppender 설정을 해주었다.

• 로그 유실 방지를 위해 neverblock을 true, discardingThreshold는 0으로 설정했다.
• 큐 사이즈는 log4j2와 같게 1024로 늘려주었다.
• 요청자 데이터는 필요없으므로 includeCallerData는 false로 설정했다.

<!-- 비동기 파일(FILE)
  includeCallerData: fasle, 비동기 로깅에서도 Method Name 및 Line Number 등 위치 정보를 출력하게 해주는 옵션
  queueSize: 기본값은 256, Log4j2와 동일하게 1024로 설정
  neverBlock: false(기본값)면 로그 발생시 Queue에 넣을 공간이 없으면 빈 공간이 생길 때 까지 블락킹 상태로 기다리며, 로그를 유실하지 않는다.
  discardingThreshold: Queue에 남은 용량이 {해당 설정값 n}%이하가 되면, WARN 미만 로그가 유실되기 시작한다.
                - 기본 값은 20이며, Queue 남은 용량이 20%이하가 되면 로그 유실이 발생한다.
                - 0으로 세팅하면 Queue에 쌓인 로그를 드랍하지 않는다.
-->
<appender name="FILE-ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="FILE" />
    <includeCallerData>false</includeCallerData>
    <discardingThreshold>0</discardingThreshold>
    <queueSize>1024</queueSize>
    <neverBlock>true</neverBlock>
</appender>

Jmeter를 사용하여 쓰레드 8개로 총 10번 API를 반복 실행하여 성능을 측정했다.

• Thread group: 8
• Loop Count: 10

기본 appender

• 처리량: 7.8 t/s

AsyncAppender

• 처리량: 9.9 t/s (기본 Appender보다 약 1.3배 더 빠름)

성능 측정 결과 AsynAppender가 약 1.3배 더 빠르게 기록되는 것을 확인할 수 있었다.