개요
Logback을 이용한 Logging과, Logging을 하기 위해 로그를 어떻게 찍어야 할지 고민했던 부분과, 로그를 찍으면서 생긴 여러 가지 트러블 슈팅들을 기록하기
전반적으로 블로그들을 많이 찾아보았지만 Logback에 대한 이론 설명이 주를 이루고 있어서 로그를 어떻게 찍어야 할지 어떻게 시작해야 할지 감이 안 왔지만 차근차근해본 과정들을 기록해 보았다!!
Logback을 선택한 이유와 Logback에 대해
예시로
ProductUpdateService라는 인터페이스를 만들고
해당 인터페이스에는
public interface ProductUpdatingService {
void updateProductViews(Long productId);
void updateProductInfo(ProductInfoUpdateDto productInfoUpdateDto, ProductImageInfoUpdateDto productImageInfoUpdateDto);
}
위와 같은 메서드들이 있고
public class ProductUpdateServiceImpl implements ProductUpdatingService{
추가로
위와 같이 구현체를 만들지 않으면 위에서 본 메서드들은 호출이 되나 기능을 할 수 없거나, 예외가 뜰 것이다.
이와 마찬가지로
SLF4J는 로깅을 하기 위한 기능을 추상화해 놓은 인터페이스이다.
trace(), debug(), info(), warn(), error() 등의
인터페이스만 있다면 해당 기능을 사용할 수가 없다.
이에 따른 구현체로 있는 것이.
LogBack과 Log4j이다.
LogBack 파일 구조 설계를.. 난 어떻게 했냐면요 ...
Logback 파일 구조 설계
기존에 내가 작성했던 logback-spring.xml은 위와 같은 형식이었다.
xml파일이 안 그래도 보기 힘들다고 생각했는데 모든 요소가 안에 있으니 가독성도 떨어지고,
무엇보다 휴먼에러 발생확률이 너무 높다는 것이다.
그리고 패턴의 경우에도 하드코딩으로 써버리니까 수정을 하기 위해 xml파일을 뒤져야 한다는 점이 매우 불편했다.
"이런 경우 어떤 느낌인지 맛보기"
<configuration scan="true" scanPeriod="5 seconds">
<!-- 날짜 변수 정의 -->
<timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
<!-- 로그 패턴 설정 -->
<property name="NOT_PROD_LOG_PATTERN"
value="[%d{yyyy-MM-dd HH:mm:ss}] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>
<property name="PROD_SYSTEM_INFO_LOG_PATTERN"
value="{"metadata":{ "timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level"},"message":"%msg"}%n"/>
<property name="PROD_WARN_LOG_PATTERN"
value="{"metadata":{ "timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level","exceptionClass":"%X{exceptionClass}","exceptionMethod":"%method"},"message":"%msg","exceptionCauseArgs":"%X{exceptionCauseArgs}","stackTrace":"%X{stackTrace}","stackTrace2":"%ex{full}"}%n"/>
<property name="PROD_INFO_LOG_PATTERN"
value="{"metadata":{ "timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level","user":"%X{user}","className":"%C", "methodName":"%M"},"message":"%msg"}%n"/>
<!-- 시스템 INFO 로그 설정 -->
<appender name="FILE_INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./log/info/info-${BY_DATE}.log</file>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder>
<pattern>${PROD_SYSTEM_INFO_LOG_PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>./backup/info/info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
</appender>
<!-- WARN 로그 설정 -->
<appender name="FILE_WARN" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./log/warn/warn-${BY_DATE}.log</file>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>WARN</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder>
<pattern>${PROD_WARN_LOG_PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>./backup/warn/warn-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
</appender>
<!-- ERROR 로그 설정 -->
<appender name="FILE_ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./logs/error/yazoba-error-${BY_DATE}.log</file>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder>
<pattern>${PROD_WARN_LOG_PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>./backup/error/error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
</appender>
Root Logger
<root level="INFO">
<appender-ref ref="FILE_INFO"/>
<appender-ref ref="FILE_WARN"/>
<appender-ref ref="FILE_ERROR"/>
</root>
<logger name="com.gulbi.Backend.global.error" level="WARN" additivity="false">
<appender-ref ref="FILE_WARN"/>
</logger>
<logger name="com.gulbi.Backend.global.error" level="ERROR" additivity="false">
<appender-ref ref="FILE_ERROR"/>
</logger>
</configuration>
XML 요소를 분리를 해서 가독성 및 재사용성을 높여보자
위와 같이 패턴만 모아 놓은 XML파일, Appender를 모아 놓는 XML파일들을 정의를 하고.
최종적으로 Logback-spring.xml에서는 분리된 Pattern 들과 Appender들을 취합해서 내가 원하는 조합으로 만들면 된다.
<configuration scan="true" scanPeriod="5 seconds">
<!-- 날짜 변수 정의 -->
<timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
<!-- appender 파일들 포함 -->
<!-- <include resource="console-appender.xml"/>-->
<include resource="./appAppender/app-file-error-appender.xml"/>
<include resource="./appAppender/app-file-warn-appender.xml"/>
<include resource="./appAppender/app-file-info-appender.xml"/>
<include resource="./systemAppender/file-info-appender.xml"/>
<include resource="./systemAppender/file-warn-appender.xml"/>
<include resource="./systemAppender/file-error-appender.xml"/>
<!-- 패턴 파일 포함 -->
<include resource="logback-pattern.xml"/>
<!-- <appender-ref ref="CONSOLE"/>-->
<logger name="com.gulbi.Backend.global.error" level="ERROR" additivity="false">
<appender-ref ref="APP-ERROR"/>
</logger>
<logger name="com.gulbi.Backend.global.error" level="WARN" additivity="false">
<appender-ref ref="APP-WARN"/>
</logger>
<logger name="com.gulbi.Backend.global.util.logging" level="INFO" additivity="false">
<appender-ref ref="APP-INFO"/>
</logger>
<root level="INFO">
<appender-ref ref="SYSTEM-INFO"/>
<appender-ref ref="SYSTEM-WARN"/>
<appender-ref ref="SYSTEM-ERROR"/>
</root>
</configuration>💡<include>로 필요한 파일들만 임포트 함으로써 가독성도 좋아짐을 볼 수 있다.
Spring 로그 패턴 설계
Log Pattern을 설계 과정과 이유
<configuration>
<!-- 콘솔 로그 패턴 -->
<property name="NOT_PROD_LOG_PATTERN"
value="[%d{yyyy-MM-dd HH:mm:ss}] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>
<!-- 시스템 인포 로그 패턴 -->
<property name="PROD_SYSTEM_INFO_LOG_PATTERN"
value="{"metadata":{"timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level", "className":"%class", "method":"%method"}, "message":"%replace(%msg{full}){'\n','|'}"}%n"/>
<!-- 시스템 경고,에러 로그 패턴 -->
<property name="PROD_SYSTEM_WARN_LOG_PATTERN"
value="{"metadata":{"timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level", "exceptionClass":"%class", "exceptionMethod":"%method"}, "message":"%replace(%msg{full}){'\n','|'}", "stackTrace":"%replace(%ex{full}){'\n','|'}"}%n"/>
<!-- 서비스 에러 패턴 -->
<property name="PROD_APP_ERROR_LOG_PATTERN"
value="{"metadata":{"timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level", "exceptionClass":"%X{exceptionClass}", "exceptionMethod":"%method"}, "message":"%msg", "exceptionCauseArgs":"%X{exceptionCauseArgs}", "stackTrace":"%X{stackTrace}", "stackTrace2":"%replace(%ex{full}){'\n','|'}"}%n"/>
<property name="PROD_APP_WARN_LOG_PATTERN"
value="{"metadata":{"timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level", "exceptionClass":"%X{exceptionClass}", "exceptionMethod":"%method"}, "message":"%msg", "exceptionCauseArgs":"%X{exceptionCauseArgs}"}%n"/>
<!-- 서비스 인포 패턴 -->
<property name="PROD_INFO_LOG_PATTERN"
value="{"metadata":{"timestamp":"%d{yyyy-MM-dd HH}", "level":"%-5level", "className":"%X{className}", "userEmail":"%X{userEmail}"}, "executionTime":"%X{executionTime}", "message":"%msg"}%n"/>
</configuration>
먼저! 로그 설계전 이분의 블로그를 참고를 해서 아이디어를 얻었다!
팀 로깅 전략 세우기
로그는 시스템의 추억이다
velog.io
솔직히 로그를 파일시스템으로써 남기고 가지고만 있으려면 나도 머리 아프게 고민을 하지 않았을 것이다.
추후 로키 혹은 엘라스틱서치에 대이터를 밀어놓고 그라파나, 키바나로 시각화를 해야 의미가 있을 텐데. 로그를 내 마음대로 찍는다면 나는 읽지만 위에 나열한 친구들이 외국어로 생각하고 안 읽어버린다.
로그 패턴이란 내가 어떤 식으로 로그를 찍을 것인지 결정을 하는 부분이다
내가 시스템을 운영할 때 로그에서 어떤 정보들을 뽑아내야 할지 생각을 하고 접근을 하는 게 바람직하다.
나의 경우는 System Log, App Log 두 가지로 분리를 하였다.
💡형식은 JSON, 그리고 줄 바꿈은 일어나지 않도록 replace를 이용해 "|"로 구분을 하였다. JSON이어도 한 줄로 되어있지 않으면 로그분석 도구에서 로그를 똑바로 읽어오지 못하는 현상을 발견했기 때문이다.
System Log
system Log의 경우에는 런타임 중에 발생하는 로그들 흔히
Info의 경우에는
timestamp: 년-월-일 시간 형식의 타임스탬프
level: 5자리로 정렬된 로그 레벨
className: 로그를 생성한 클래스의 전체 이름
method: 로그를 생성한 메서드 이름
message: 로그 메시지 전체 내용 (줄 바꿈은 '|'로 대체)
Warn과 Error의 경우에는 info 단 게의 로깅정보에 추가로 StackTrace를 추가를 했다. 추후에 디버깅 시 참고를 하기 위함이다.
App Log
코드를 짜면서 내가 의도한 유의미한 정보를 남기기 위해 내가 별도로 분리를 한 Log이다.
App Log에서 Info 단계에서 로깅은 AOP를 이용하여
어떤 클라이언트가 어떤 api를 요청했는지 그리고 해당 API의 총 실행시간은 얼마나 걸렸는지를 로깅을 했다.
Warn과 Error레벨을 어떻게 분리를 했는데?
내가 충분히 예상을 해서 예외처리를 해놓은 예외의 경우는 Warn레벨
그 외에 나의 예상을 벗어나서 발생한 예외를 Error 레벨로 처리를 하였다.
예외가 발생한다면 예외를 던지기 전에 해당 객체에 예외와 관련된 정보를 넣어주었다.
그 후 BusinessException까지 도달한다면 ExceptionHandler에 의해 해당 객체 값이 도달을 하게 될 것이고.
클라이언트에게 실패 응답을 날려주기 전 해당 객체의 값을 추출하여 로깅을 하도록 하였다.
서비스단에서 예외가 발생했을 때, 인지한 예외의 경우는 스택트레이스를 넣지 않도록 하였다.
그 외에 개발과정에서 인지하지 못한 예외가 발생한 경우 StackTrace를 넣어줌으로 warn레벨인지 error레벨인지 구분을 하였다.
추가로 예외가 발생했을 시 어떤 Args가 들어왔는지 또한 로깅을 하였다
다시 XML로 돌아와서.. Logback Appender 설계
Appender 설계
appender는 실질적으로 로깅을 하기 위해
로그의 형태, 어디에 출력할지(파일, 콘솔창)등을 종합적으로 결정하는 부분이다.
INFO, WARN, ERROR 모두 파일 이름과 레벨, 패턴적용 부분을 제외하면 전부 동일하다.
각 요소가 어떤 걸 의미하는지는 생각하도록 하겠다.
<configuration>
<appender name="APP-ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>./log/app/error/yazoba-error-${BY_DATE}.log</file>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder>
<pattern>${PROD_APP_ERROR_LOG_PATTERN}</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>./backup/error/yazoba-error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>100MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>3GB</totalSizeCap>
</rollingPolicy>
</appender>
</configuration>
Logback-spring.xml에 조합을 하자
빨간 네모와 주황색 네모는 별도로 정의해 둔 Pattern.xml 그리고 Appender.xml을 임포트 하기 위해 <include/>를 사용함을 볼 수 있을 것이다.
여기서 유의해야 할 사항은 Appender.xml 에 <include/>를 이용해서 Pattern.xml을 임포트 한다고 해서 적용이 되지 않는다.
logback-spring.xml에 임포트를 해주어야 한다.
노란색 네모의 경우는 App Log에 대한 부분이다.
name을 보면 경로명이 적혀있는데 해당경로명은
logger.error()
와 같은 로그를 실제로 찍는 클래스의 이름이 들어가야 한다
나의 경우에는 ExceptionHandler에서 Warn과 Error레벨을 처리하기에 경로를 저렇게 넣어주었고
Info 레벨의 경우에는 AOP를 이용해서 처리를 했기 때문에 AOP클래스의 경로를 넣어 주었다.
초록색 부분은 System Log를 기록하기 위한 부분이다.
마지막으로 하늘색 부분은 Appender.xml에 name을 적어주었을 텐데 해당 name을 적어주어야 한다라는 취지로 넣어 보았다. 휴먼에러가 가장 많이 발생했던 지점..
트러블 슈팅
대부분은 휴먼 에러가 주를 이룬다. 며칠 동안 찢기면서 내가 실수 한 부분에 대해 체크리스트를 만들어 보았다..
체크리스트!!
💡 included 할 때 절대경로 혹은 상대경로를 정확히 입력했나요?
💡 Appender에 정의한 LogLevel과 <root> 혹은 <Logger>에 정의된 레벨과 일치한가요?
💡 XML파일의 들여 쓰기가 정말 잘 되어 있나요?
💡 <logger name="">의 경로에 logger.info(), logger.error()가 정말 존재하나요? 혹은 가슴에 손을 얹고 경로가 정확한 가요?
💡 본인이 작성한 Pattern이 정말 Logback이 인식할 수 있는 유효한 패턴인가요?
Console과 File을 같이 쓰면 둘 다 적용이 안 되는 기이한 현상이 나타난다.
Appender.xml에 Pattern.xml을 임포트 하지 말 것.
Appender.xml
RollingFileAppender에서 파일 이름 패턴(fileNamePattern)이 중복
RollingFileAppender에서 파일 이름 패턴(fileNamePattern)이 중복되는 문제.
같은 fileNamePattern을 가진 여러 개의 appender가 있을 때, Logback은 이를 구분할 수 없어 충돌 오류를 발생시킴.
