1. 개요
- 스프링 부트 환경에서 기본으로 제공하는 LogBack을 사용하여 로그를 남겨보자
- spring.profiles.active를 사용하여 운영, 개발 환경에 따라 로그 설정을 분기하여 적용해보자
[참고 : https://goddaehee.tistory.com/206 깃대희의 작은공간]
2. LogBack이란?
- LogBack이란 Log4j를 만든 개발자가 Log4j를 기반으로 속도와 메모리 점유율을 개선하여 만든 로깅 프레임워크이다.
- org.slf4j.Logger 인터페이스의 구현체이다.
>> 코드 작성 시 이 인터페이스를 임포트해주면 된다.
3. LogBack 특징
- Level : 로그 레벨을 설정할 수 있다.
- Appender : 출력 방법을 선택할 수 있다. ex) Console, RollingFile 등
- Logger : 로그마다 다른 설정을 적용시킬 수 있다.
- Authmatic Reloading Configuration File : 특정 시간마다 별도의 스레드를 통해 설정 파일 변경 여부 파악 및 적용이 가능하다. > logback 설정 변경 시 서버 재시작이 필요없다.
4. 프로젝트 세팅
1) Controller - 로그를 찍기 위한 클래스
2) application.properties - spring.profiles.active 설정 추가
3) logback-spring.xml - logback 설정
4) logback-{운용환경}.properties - logback 설정파일에서 로드할 상수 (로그파일, 레벨 등)
4.1. Controller
/api/log 요청 시 trace부터 error 까지의 로그를 쌓는 메서드를 작성한다.
@Controller
@RequestMapping("/api")
public class FileController {
private final Logger logger = LoggerFactory.getLogger(this.getClass());
@GetMapping("/log")
@ResponseBody
public ResponseDTO main() {
logger.trace("trace Log");
logger.debug("debug Log");
logger.info("info Log");
logger.warn("warn Log");
logger.error("error Log");
return null;
}
}
4.2. application.properties
spring.profiles.active=dev 를 추가하여 개발 및 운영 환경을 정의해준다.
#서버포트
server.port=9090
#운용환경 : 개발
spring.profiles.active=dev
4.3. logback-spring.xml
resource 경로에 logback-spring.xml 을 생성한 후 logback 설정을 정의한다.
* resource 경로에 logback-spring.xml 파일이 있으면 서버 기동 시 자동으로 로드한다.
<?xml version="1.0" encoding="UTF-8"?>
<!-- 10초마다 파일 변화를 체크하여 갱신시킨다. -->
<configuration scan="true" scanPeriod="10 seconds">
<!-- spring.profile에 따른 설정파일 분기 -->
<springProfile name = "prod">
<property resource = "logback-prod.properties"/>
</springProfile>
<springProfile name = "dev">
<property resource = "logback-dev.properties"/>
</springProfile>
<!-- 루트 로그 레벨 -->
<property name ="LOG_LEVEL" value = "${log.config.level}"/>
<!-- 로그 파일 경로 -->
<property name ="LOG_PATH" value = "${log.config.path}"/>
<!-- 로그 파일 명 -->
<property name ="LOG_FILE_NAME" value = "${log.config.filename}"/>
<property name ="ERR_LOG_FILE_NAME" value = "${log.config.filename}_error"/>
<!-- 로그 파일 패턴 -->
<property name ="LOG_PATTERN" value = "%-5level %d{yyyy-MM-dd HH:mm:ss}[%thread] [%logger{0}:%line] - %msg%n"/>
<!-- 콘솔 Appender 설정 -->
<appender name ="CONSOLE" class ="ch.qos.logback.core.ConsoleAppender">
<encoder class ="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${LOG_PATTERN}</pattern>
</encoder>
</appender>
<!-- 파일 Appender 설정 -->
<appender name="FILE" class ="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 파일 경로 설정 -->
<file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>
<!-- 로그 패턴 설정 -->
<encoder class = "ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${LOG_PATTERN}</pattern>
</encoder>
<!-- 롤링 정책 -->
<rollingPolicy class = "ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- gz, zip 등을 넣을 경우 자동 로그파일 압축 -->
<fileNamePattern>${LOG_PATH}/%d{yyyy-MM-dd}/${LOG_FILE_NAME}_%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<!-- 파일당 최고 용량 -->
<maxFileSize>10MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!-- 로그파일 최대 보관주기 -->
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
<appender name = "ERROR" class ="ch.qos.logback.core.rolling.RollingFileAppender">
<filter class ="ch.qos.logback.classic.filter.LevelFilter">
<level>error</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<file>${LOG_PATH}/${ERR_LOG_FILE_NAME}.log</file>
<!-- 로그 패턴 설정 -->
<encoder class = "ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>${LOG_PATTERN}</pattern>
</encoder>
<!-- 롤링 정책 -->
<rollingPolicy class = "ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- gz, zip 등을 넣을 경우 자동 로그파일 압축 -->
<fileNamePattern>${LOG_PATH}/%d{yyyy-MM-dd}/${ERR_LOG_FILE_NAME}_%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<!-- 파일당 최고 용량 -->
<maxFileSize>10MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!-- 로그파일 최대 보관주기 -->
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
<root level = "${LOG_LEVEL}">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ERROR"/>
</root>
<logger name="org.apache.ibatis" level = "DEBUG" additivity = "false">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ERROR"/>
</logger>
</configuration>
- springProfile 태그를 사용하여 시스템 변수의 spring.profile.active 값을 조회할 수 있다. 이 값에 따라 logback-prod, logback-dev 파일 중 하나를 로드하여 설정파일의 프로퍼티로 사용한다.
4.4. logback-dev.properties
- 개발환경에서는 로그레벨을 debug로 설정한다.
#로그 레벨
log.config.level=debug
#로그파일 경로
log.config.path=/logs
#로그파일 명
log.config.filename=reckey
4.5. logback-prod.properties
- 운영 환경에서는 로그레벨을 info로 설정한다.
#로그 레벨
log.config.level=info
#로그파일 경로
log.config.path=/logs
#로그파일 명
log.config.filename=reckey
5. 테스트
spring.profile.active를 prod 설정하면 로그레벨이 INFO로 잡혀있어 불필요한 로그는 조회되지 않지만 dev로 설정할 경우 서버 기동 시 발생되는 로그, DB 로그 등이 중구난방으로 나오게 된다.
원인은 dev로 설정할 경우 logback 설정의 루트 로그 레벨이(root level) 값이 debug로 설정되어 어플리케이션 내 모든 클래스의 debug 로그가 찍히기 때문이다.
이런 로그들은 특수한 목적이 없는 한 debug보단 info로 올리는 것이 좋다. 이를 위해서는 logger 태그를 사용하여 클래스별 로그 레벨 분기처리를 해야한다.
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [AnonymousAuthenticationFilter:96] - Set SecurityContextHolder to anonymous SecurityContext
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [FilterSecurityInterceptor:210] - Authorized filter invocation [GET /api/log] with attributes [permitAll]
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [FilterChainProxy:323] - Secured GET /api/log
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [DispatcherServlet:91] - GET "/api/log", parameters={}
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [PropertySourcedRequestMappingHandlerMapping:108] - looking up handler for path: /api/log
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [RequestMappingHandlerMapping:522] - Mapped to com.reckey.controller.FileController#main()
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [FileController:24] - debug Log
INFO 2021-10-07 02:11:23[http-nio-9090-exec-1] [FileController:25] - info Log
WARN 2021-10-07 02:11:23[http-nio-9090-exec-1] [FileController:26] - warn Log
ERROR 2021-10-07 02:11:23[http-nio-9090-exec-1] [FileController:27] - error Log
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [RequestResponseBodyMethodProcessor:268] - Using 'application/json;q=0.8', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, application/signed-exchange;v=b3;q=0.9, */*;q=0.8] and supported [application/json, application/*+json, application/json, application/*+json]
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [RequestResponseBodyMethodProcessor:298] - Nothing to write: null body
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [DispatcherServlet:1131] - Completed 200 OK
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [HttpSessionSecurityContextRepository:346] - Did not store anonymous SecurityContext
DEBUG 2021-10-07 02:11:23[http-nio-9090-exec-1] [SecurityContextPersistenceFilter:118] - Cleared SecurityContextHolder to complete request
DEBUG 2021-10-07 02:11:25[reckeyPool housekeeper] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:11:25[reckeyPool housekeeper] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
5.1. 특정 클래스 분기처리 (로그레벨 INFO로 격상)
일단 분기처리할 클래스의 경로를 확인해보자. 현재 로그 설정으로는 클래스 명만 나오고 있기 때문에 클래스 경로를 파악하기 힘들다. 로그 패턴에 클래스 경로 패턴인 %C를 다음과 같이 추가해보자. 자동 리로드 설정이 있으므로 서버 재시작은 하지 않아도 된다.
<property name ="LOG_PATTERN" value = "%-5level %d{yyyy-MM-dd HH:mm:ss}[%thread] [%C] [%logger{0}:%line] - %msg%n"/>
그리고 다시 요청을 보내면 다음과 같이 클래스 경로가 함께 조회된다.
INFO 2021-10-07 02:14:37[restartedMain] [org.springframework.boot.StartupInfoLogger] [ReckeyApplication:61] - Started ReckeyApplication in 0.703 seconds (JVM running for 3806.024)
DEBUG 2021-10-07 02:14:37[restartedMain] [org.springframework.boot.availability.ApplicationAvailabilityBean] [ApplicationAvailabilityBean:77] - Application availability state LivenessState changed to CORRECT
INFO 2021-10-07 02:14:37[restartedMain] [org.springframework.boot.devtools.autoconfigure.ConditionEvaluationDeltaLoggingListener] [ConditionEvaluationDeltaLoggingListener:63] - Condition evaluation unchanged
DEBUG 2021-10-07 02:14:37[restartedMain] [org.springframework.boot.availability.ApplicationAvailabilityBean] [ApplicationAvailabilityBean:77] - Application availability state ReadinessState changed to ACCEPTING_TRAFFIC
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@36e9f17b
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@73eb69c2
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@439a7476
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@42521e57
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@3bc95d4f
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@13c4968d
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator] [HikariPool:728] - reckeyPool - Added connection org.postgresql.jdbc.PgConnection@36d6947
DEBUG 2021-10-07 02:14:37[reckeyPool connection adder] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - After adding stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:15:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:15:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
DEBUG 2021-10-07 02:15:37[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:15:37[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
DEBUG 2021-10-07 02:16:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:16:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
DEBUG 2021-10-07 02:16:37[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:16:37[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
DEBUG 2021-10-07 02:17:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:421] - reckeyPool - Pool stats (total=10, active=0, idle=10, waiting=0)
DEBUG 2021-10-07 02:17:07[reckeyPool housekeeper] [com.zaxxer.hikari.pool.HikariPool] [HikariPool:517] - reckeyPool - Fill pool skipped, pool is at sufficient level.
org.springframework경로의 여러 클래스와 com.zaxxer.hikari로 시작하는 여러 클래스에서 DEBUG레벨로 로그들이 찍히고 있다. (히카리 로그는 DB연결로 인함입니다. 신경쓰지않으셔도됩니다.) 이 클래스들만 DEBUG레벨에서 INFO 레벨로 올린다면 이 문제가 해결될 것이다.
logback-spring.xml 파일의 logger 태그에 분기처리할 클래스를 다음과 같이 추가한다.
name에 들어가는 경로의 하위 모든 클래스에서 발생하는 로그를 INFO 레벨로 올리게 된다.
<logger name="org.springframework" level = "INFO" additivity = "false">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ERROR"/>
</logger>
<logger name="com.zaxxer.hikari" level = "INFO" additivity = "false">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="FILE"/>
<appender-ref ref="ERROR"/>
</logger>
이제 실제 요청을 보내면 다음과 같이 불필요한 debug 레벨의 로그들을 쌓지 않게 된다.
DEBUG 2021-10-07 02:26:21[http-nio-9090-exec-1] [com.reckey.controller.FileController] [FileController:24] - debug Log
INFO 2021-10-07 02:26:21[http-nio-9090-exec-1] [com.reckey.controller.FileController] [FileController:25] - info Log
WARN 2021-10-07 02:26:21[http-nio-9090-exec-1] [com.reckey.controller.FileController] [FileController:26] - warn Log
ERROR 2021-10-07 02:26:21[http-nio-9090-exec-1] [com.reckey.controller.FileController] [FileController:27] - error Log
6. 마치며
스프링 부트에서 로그백을 사용하여 로그를 남겨본 것은 처음이다. 생각보다 되게 간단하고, log4j 같은 경우 로그파일 리로드 설정을 외부 설정파일에서 해줘야하는데 logback은 리로드되는 기능이 설정 파일 안에 있어서 좋은것 같다.
