[쿠링] 효율적인 Log 관리를 위한 여정 - 1

 

1. 문제가 되는 상황

여유가 생겼을 때 쿠링이 Log를 남기고 있는 과정에 대하여 한번 고민해보고 싶었다.

 

오늘 글은 크게 3가지에 대한 고민으로부터 시작되었다.

1) Log의 level이 적합한가? (이번 글에서 해결할 내용)

2) Log 파일의 사이즈가 너무 커지지 않도록 나뉘어 저장되고 있는가? (이번 글 에서 해결할 내용)

3) Log의 모니터링이 편리하게 되고 있는가? (추가 글에서 다룰 예정)

 

일단 2가지에 대하여 답해보면, 현 쿠링은 "아니요"라고 답할 수 있을 거 같다.

크게 기준없이 설정된 log들의 level, 더 나아가 log를 보기 위해서는 직접 EC2에 접근하여 로그 파일을 살펴봐야 했다...

 

또한 로그가 중요하다는 생각에 무분별하게 남기는 것이 과연 좋은가?

나는 습관적으로 예외 상황이 발생하면 ERROR 레벨로 로그를 남기는 경향이 있다...

 

이런 경우 특정 시간 내 에러 로그가 일정 수치 이상 쌓이면 알람을 발생시키도록 구성하는 것 이 좋을 수 있다.
정상적이지 않은 모든 상황에서 전부 ERROR 레벨로 처리하게 되면 불필요하게 많은 알람들로 인해 정작 봐야할 심각한 에러 로그들도 놓칠 수 있기 때문이다...

 

이를 하나하나 해결해 나가 보자!

 

2. Log의 Level 수정하기

우선 모든 로그의 level의 기준에 대하여 고민해 볼 시간이 필요했다.

각 로그의 level에 대하여 고민해 보고, 기준을 정해보자!!

 

2-1) 기준 설정

DEBUG

• 개발 혹은 테스트 단계에서 해당 기능들이 올바르게 작동하는지 확인하기 위한 로그 레벨이다.
• 요즘은 워낙 IDE의 디버거가 좋아져서 로컬 개발 단계에서는 활용할 일이 적지만, 배포 환경에서 도움이 될 수 있을 것 같다.
• 다른 레벨들과 달리 운영 환경에서는 남기고 싶지 않은 로그 메시지를 위한 레벨이다.

INFO

• 애플리케이션에서 정상 작동에 대한 정보 즉, 어떤 일이 발생했음을 나타내는 표준 로그 레벨
• 애플리케이션 상태, 설정 또는 외부 리소스와의 상호 작용과 같은 상태 확인을 위한 이벤트를 나타낸다.
  • 예를 들어, 인증 API의 백엔드 시스템에서 인증이 성공했는지 여부에 따라 사용자가 인증을 요청한 정보가 INFO 레벨의 로그로 남긴다.
  • 애플리케이션이 시작되거나 종료되는 시점, 중요한 작업이 완료되거나 실행되는 시점 등의 경우에도 남길 수 있다.
  • 예를 들어 쿠링에서는 공지를 scrap해온 후, 몇 건을 성공적으로 저장했는지, scrap이 몇 시 몇 분에 시작했는지를 남길 수 있을 것 같다.
• INFO 로그는 시스템을 파악하는데 유익한 정보여야만 한다, 무의미한 정보를 남길 필요가 없다.

WARN

• 애플리케이션에서 잠재적으로 문제가 될 수 있는 상황일 때 남기는 로그 레벨
  • 예를 들어 공지 scrap을 위해 학교 서버에 로그인 시, 로그인이 실패하는 것은 ID, PW 변경 요청등으로 인하여 발생할 수 있는 일반적인 문제 상황이다.
  • 이럴 때는 WARN 레벨로 책정하고, 로그인이 5번 연속 실패하는 등 특정 기준치를 넘길 경우 ERROR 레벨로 남기는 것이 좋다.
  • 이와 유사하게 예상치 못한 입력 (사용자가 유효하지 않은 입력을 제공한 경우 - 예: 이메일 형식이 아닌 입력), 리소스 제한 (파일 업로드 사이즈 초과 등)과 같은 경고를 기록할 수 있다.
  • 이런 경우 사용자에게 노출되는 메시지에 상세한 가이드가 필요한 것이지, 로그 레벨이 ERROR일 필요가 없다.
• 이 레벨의 메시지는 개발자가 조치를 취할 수 있도록 주의를 기울일 필요가 있는 상황을 나타낸다.

ERROR

• 애플리케이션에서 발생한 심각한 오류나 예외 상황을 나타내는 로그 레벨
• 기능 자체가 제대로 작동하지 못하는 문제이거나, 내부 시스템의 문제로 작업이 실패하는 경우 남겨야 하며 즉시 조치가 필요할 때를 의미한다.
• 운영 환경에서도 사용할 수 있다.

 

지금까지의 생각을 간단하게나마 정리해 보면,

DEBUG : 운영 환경에서는 남기고 싶지 않은 로그 메시지

INFO : 정상 작동에 대한 정보 

WARN : 잠재적으로 문제가 될 수 있는 상황

ERROR : 즉시 조치가 필요한 경우

 

위와 같은 간단한 기준을 기반으로 로그의 level을 수정해 보자!

 

2-2) Level 수정하기

2-2-1) 외부 API 연동 log (feat Firebase)

우선 외부 API에서의 예외처리를 어떻게 남겨야 할까?

쿠링 프로젝트 내부의 API가 아닌 외부 API 서비스의 호출을 100% 성공하지 못할 수도 있다. 따라서 외부 API 호출의 일정 비율이 실패하는 것이 일상인 것을 어느 정도 가정하자!

 

우선 대표적으로 firebase에 의존적으로 사용되는 sendNotificationByFcm이라는 메서드를 살펴보자!

public void sendNotificationByFcm(List<? extends Notice> noticeList) {
    List<NoticeMessageDto> notificationDtoList = createNotification(noticeList);

    try {
        this.sendNoticeMessageList(notificationDtoList);
        log.info("FCM에 {}개의 공지 메세지를 전송했습니다.", notificationDtoList.size());
        log.info("전송된 공지 목록은 다음과 같습니다.");
        for (Notice notice : noticeList) {
            log.info("아이디 = {}, 날짜 = {}, 카테고리 = {}, 제목 = {}", notice.getArticleId(), notice.getPostedDate(), notice.getCategoryName(), notice.getSubject());
        }
    } catch (FirebaseMessageSendException e) {
        log.error("새로운 공지의 FCM 전송에 실패했습니다.");
        throw new InternalLogicException(ErrorCode.FB_FAIL_SEND, e);
    } catch (Exception e) {
        log.error("새로운 공지를 FCM에 보내는 중 알 수 없는 오류가 발생했습니다.");
        throw new InternalLogicException(ErrorCode.UNKNOWN_ERROR, e);
    }
}

과연 Firebase에 한, 두 번 정도의 메시지 전송 실패는 여러 이유로 발생 가능하다. 서버의 통신 상황 자체가 문제 될 수도 있고, Firebase 서버 측에 일시적 문제가 있을 수도 있다. 이런 상황에 메시지가 전달되지 못할 수는 있지만 error로 삼을 정도로 심각한 오류라 할 수 있는가?

정말 심각한 오류 정도라면 애플리케이션 자체가 동작할 수 없을 수준이어야 한다 생각된다.

 

따라서 FirebaseMessageSend와 관련되어 있는 예외들을 warn으로 변경하자!

또한 n개의 공지를 전달했다는 정보는 기존처럼 info로 확인하는 것 이 좋다 생각하지만, 세부적으로 어떤 메시지들을 전송했는지는 운영서버에 남을 필요 없다 생각된다. 이를 DEBUG로 변경하자!

 

다음과 같이 말이다!

public void sendNotificationByFcm(List<? extends Notice> noticeList) {
    List<NoticeMessageDto> notificationDtoList = createNotification(noticeList);

    try {
        this.sendNoticeMessageList(notificationDtoList);
        log.info("FCM에 {}개의 공지 메세지를 전송했습니다.", notificationDtoList.size());
        log.debug("전송된 공지 목록은 다음과 같습니다.");
        for (Notice notice : noticeList) {
            log.debug("아이디 = {}, 날짜 = {}, 카테고리 = {}, 제목 = {}", notice.getArticleId(), notice.getPostedDate(), notice.getCategoryName(), notice.getSubject());
        }
    } catch (FirebaseMessageSendException e) {
        log.warn("새로운 공지의 FCM 전송에 실패했습니다.");
        throw new InternalLogicException(ErrorCode.FB_FAIL_SEND, e);
    } catch (Exception e) {
        log.error("새로운 공지를 FCM에 보내는 중 알 수 없는 오류가 발생했습니다.");
        throw new InternalLogicException(ErrorCode.UNKNOWN_ERROR, e);
    }
}

 

2-2-2) 사용자의 잘못된 입력에 대한 예외 log

사용자가 요청 시 입력값을 잘못 입력했거나, 지정된 범위 이상의 값을 전달하는 경우 지금은 CommonExceptionHandler에서 error level로 로그를 출력하고 있다.

 

다음 CommonExceptionHandler에서 남기고 있는 로그의 목록을 살펴보자!

- MethodArgument의 예외는 사용자의 잘못된 입력이라 error까지는 아니고, warn으로 변경하면 좋을 거 같다.

- NotFoundException 또한 해당 사용자나, 게시물을 못 찾았다는 예외인데 이 또한 error수준 이라기보다는, warn에 가깝다.

그 외의 MissingServletRequest, ConstraintViolation, HttpMediaTypeNotAcceptable 모두 warn이 적합하고,

서버 내부의 예외를 표현하는 InternalLogicException만 error로 남겨두는 것 이 적합한 거 같다.

 

2-2-3) 테스트 중에만 살펴볼 로그들

Admin용으로 사용 중인 API에서는 값만 확인해 보기 위한 로그들 있다.

예를 들면 다음과 같이 sessionId와 마지막 접근 시간등이 있을 것이다.

이 로그들의 경우 운영환경에는 남지 않는 것 이 좋다. 특히 sessionId가 로그에 남아 보이는 것은 좋지 못하다 생각된다.

이들의 level은 debug로 변경하자!

 

2-3-4) sql 쿼리 로그 제거하기

운영서버에서 sql 쿼리로그를 남기는 것 또한 성능상 좋지 못하다 생각되었다.

기존에는 다음과 같이 쿼리 또한 로그에 남고 있었지만, 이 또한 application.yml에 설정을 통해 제거해 주었다!

다음과 같이 p6 spy의 decorator를 false로 설정해 주었다!

decorator:
  datasource:
    p6spy:
      enable-logging: false

 

3. Log 저장을 날짜별로 저장하기

우선 logback-spring.xml파일을 다음과 같이 만들어 주었다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 이 곳에 추가할 properties를 넣는다. -->
    <property name="LOGS_ABSOLUTE_PATH" value="./logs/kuring"/>

    <!-- 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] %magenta([%thread]) %highlight(%-5level) %cyan(%logger{36}) - %msg%n</Pattern>
        </layout>
    </appender>

    <!-- Info 레벨의 이름을 가진 로그를 저장할 방식을 지정한다. -->
    <appender name="INFO_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOGS_ABSOLUTE_PATH}/info.log</file> <!-- 파일을 저장할 경로를 정한다, 도커 사용 시 볼륨매핑 해주어야함 -->
        <!-- filters 종류 키워드로 확인 -->
        <filter class="ch.qos.logback.classic.filter.LevelFilter"> <!-- 지정한 레벨과 같은 로그이벤트 필터링 수행 -->
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
            <onMismatch>DENY</onMismatch> <!-- 지정 레벨과 맞지 않으면 onMisMatch 에 지정에 따라 수행, DENY -> print 하지않음 -->
        </filter> <!-- 레벨별 필터링이 필요없을 경우 filter class 관련된 부분을 삭제하면 됨-->
        <encoder>
            <Pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %magenta([%thread]) %highlight(%-5level) %cyan(%logger{36}) - %msg%n</Pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOGS_ABSOLUTE_PATH}/was-logs/info/info.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <!-- 해당 패턴 네이밍으로 이전 파일이 기록됨 -->
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>50MB</maxFileSize> <!-- 한 파일의 최대 용량 -->
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory> <!-- 한 파일의 최대 저장 기한 -->
            <totalSizeCap>500MB</totalSizeCap> <!-- 전체 로그파일 크기 제한, 500MB를 넘으면 오래된거 삭제 -->
        </rollingPolicy>
    </appender>

    <appender name="WARN_OR_MORE_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOGS_ABSOLUTE_PATH}/warn-or-more.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter"> <!-- 지정레벨 이상의 로그만 print 하는 필터 -->
            <level>WARN</level>
        </filter>
        <encoder>
            <Pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative] %magenta([%thread]) %highlight(%-5level) %cyan(%logger{36}) - %msg%n</Pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOGS_ABSOLUTE_PATH}/was-logs/warn-or-more/warn-or-more.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>50MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory> <!-- 한 파일의 최대 저장 기한 -->
            <totalSizeCap>500MB</totalSizeCap> <!-- 전체 로그파일 크기 제한, 500MB를 넘으면 오래된거 삭제 -->
        </rollingPolicy>
    </appender>

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

rollingPolicy를 통해 날마다 새로운 로그파일로 저장하도록 설정해 주었다!

 

RollingFileAppender

로그 파일을 롤오버 하는 기능으로 FileAppender를 확장하여서 사용합니다. RollingFileAppender를 사용하기 위해서는 중요한 하위 구성 요소는 RollingPolicy와 TriggeringPolicy입니다.

• RollingPolicy
  • 롤오버에 필요한 작업을 수행합니다.
  • 무엇을 할지 담당합니다.
• TriggeringPolicy
  • 롤오버가 발생하는지 여부와 정확한 시기를 결정합니다.
  • 언제 할지 담당합니다.

RollingFileAppender를 사용하기 위해서는 RollingPolicy와 TriggeringPolicy가 모두 설정되어 있어야 합니다.

 

4. 참고

egovframework:rte3:fdl:설정_파일을_사용하는_방법 [eGovFrame]

 

간단하게 스프링에서 로깅 남기기

 

[Spring] logback 파헤치기 (로그 레벨 설정, 프로필별 로그 설정, 글자 색상 변경)