[Spring] 에러 로깅하기 - Logback을 사용해서 ERROR 레벨만 파일로 로그를 남겨보자!

🌱 들어가기 전

이번 장바구니 미션에서는 프론트 크루들과 협업을 해야 했기 때문에 앞으로 에러 로그를 볼 일이 많아질 것 같다고 생각했다.

배포 스크립트를 작성하면서 스프링이 띄워질 때의 로그는 볼 수 있었지만, 에러에 대한 로그만 빠르게 확인하면 좋을 것 같아서 이번 미션에 나름의 삽질을 곁들여가며 적용해보았다 😊 

 

---

 

🌱 문제 상황

배포 스크립트를 작성하며 아래의 문장이 나를 혼란스럽게 했다.

nohup sudo java -jar $JAR_NAME >> $REPOSITORY/deploy.log 2> $REPOSITORY/deploy-err.log &

nohup : 터미널을 종료해도 계속 실행하기.

java -jar $JAR_NAME : jar 파일 실행하기.

>> : 출력 리다이렉션. jar의 실행 결과를 파일로 저장하고 싶어! (deploy.log 파일로 저장)

- 참고로, >>의 경우 기존의 파일에 내용을 추가하는 것이고 새롭게 덮어씌우고 싶다면 >을 사용하자.

⭐️ 2> : 표준 오류 출력 리다이렉션. jar의 실행 결과 중 '표준 오류'에 대해서 deploy-err.log 저장하기

& : 백그라운드로 실행하기. 기본적으로 쉘은 명령어가 종료될 때까지 계속 대기하기 때문에 백그라운드로 실행하여 다른 작업도 진행할 수 있도록 만들기.

 

나는 여기서 2> $REPOSITORY/deploy-err.log 이 친구 때문에 스프링에서 에러 로그가 발생하면 deploy-err.log로 저장될 것이라고 생각했다. 하지만... 아무리 해도 아무것도 저장이 되지 않아서 절망하고 있었다.

이는, 2>가 '표준 오류 출력'에 대해서 리다이렉션을 하는 것이기 때문이다.

 

💬 표준 오류 출력이 뭘까?
보통 쉘에서 명령어를 실행하게 되면, 해당 명령어에 대한 출력은 표준 출력 (STDOUT)을 통해 나오게 된다.
하지만, 해당 명령어를 실행하는 도중에 발생하는 오류나 경고, 예외 메시지의 경우 표준 출력 (STDERR)을 통해 나오게 되는데, 예를 들어 파일을 찾을 수 없거나, 잘못된 명령어를 입력하는 것 같은, '명령어를 실행하는 도중'에 발생한 오류에 대해서 관리하게 된다.

 

나는 스프링에서 아래와 같이 에러에 대한 로그 핸들링을 하고 있었다.

@ControllerAdvice
public class ControllerExceptionHandler {

    private final Logger log = LoggerFactory.getLogger(getClass());

    @ExceptionHandler(Exception.class)
    public ResponseEntity<Void> exception(Exception e) {
        log.error(e.getMessage(), e);
        return ResponseEntity.status(HttpStatus.BAD_REQUEST).build();
    }
}

물론, 추후 기능을 개발하면서 고도화하겠지만 우선 모든 예외에 대해 로그 처리를 하기 위해서 이렇게 진행하였다.

여기서 log.error()를 사용하여 출력한 것은 단순히 로깅 라이브러리에서 제공하는 기능을 통해 오류 레벨의 로그를 기록하게 되며, 실제 출력 대상은 별도의 설정을 통해서 처리해줘야 하는 것이었다.

 

그래서, 만약 스프링에서 표준 에러로 출력하고 싶다면 아래와 같이 진행하면 된다.

@ControllerAdvice
public class ControllerExceptionHandler {

    private final Logger log = LoggerFactory.getLogger(getClass());

    @ExceptionHandler(Exception.class)
    public ResponseEntity<Void> exception(Exception e) {
        System.err.println(e);
        return ResponseEntity.status(HttpStatus.BAD_REQUEST).build();
    }
}

The "standard" error output stream.
This stream is already open and ready to accept output data.

err에 대해서 위와 같이 '표준 에러' 출력 스트림으로 지정한다고 되어 있다.

하지만... System.out.println을 통해서 로깅 처리를 안 하듯이, 에러 역시 저런 식으로 처리하는 것을 두고 볼 수 없다.

 

 

💬 근데 왜 System.out.println을 쓰면 안 될까?

로깅 라이브러리는 로그 출력 레벨을 통해 개발 환경에 따른 로그 레벨을 적용할 수 있지만, System.out.println은 그런 게 안 된다.

모두 동일한 로그가 출력되다 보니 로컬 환경에서는 debug 레벨부터, 프로덕션 환경에서 warn 레벨부터 볼 수 있도록 조절할 수 없다는 것이다.

또한, 내부적으로 synchorized를 통해 멀티 스레드 환경에서는 락이 걸리기 때문에 성능적으로도 문제가 생긴다고 한다.

자세한 건 이 레퍼런스에서 더 참고해도 좋을 것 같다 😊 

 

그렇다면, 우리는 어떻게 에러에 대한 로깅을 진행해야 할까?

 

---

 

🌱 Logback 활용하기

바로, Logback이라는 친구를 활용하는 것이다. 

Logback은 대표적인 로깅 프레임워크 중 하나로, Log4j를 대체하기 위해서 나왔다고 한다.

스프링부트의 경우 기본적으로 지원하고 있기 때문에 별도의 dependency를 설정해줄 필요가 없어서 간편하다.

 

기본적으로 Logback의 경우 Logger, Appender, Layout이라는 3가지의 클래스로 구성되어 있다.

Logger: 로그 메시지에 대한 일종의 컨텍스트로, 애플리케이션이 로그 메시지를 생성하기 위해 상호작용하는 클래스이다.

Appender: 로그 메시지를 배치하는 역할로, Logger는 둘 이상의 Appender를 가질 수 있다.

Layout: 출력될 메시지를 준비하며, 메시지 포매팅을 위한 클래스 생성을 지원한다.

 

또한, '로그 레벨'이라는 개념을 이해해야 하는데, Logback의 로그 레벨은 총 5단계로 구성되어 있다.

Trace - Debug - info - Warn - Error 순이며, 보통 다음과 같은 의미를 가진다.

TRACE: 애플리케이션 내부의 작은 단위 동작이나 메서드 호출, 변수 값 등에 대한 정보를 모두 포함한다. (엄청 방대한 양의 로그가 쌓이게 된다.) 로컬 개발 환경에서 많이 사용한다.

DEBUG: Trace보다 조금 더 상위 수준의 레벨이며, SQL에 대한 로깅을 진행할 수 있다. (경험상 로컬, 개발 서버까지 debug 레벨을 많이 사용하는 것 같다.)

INFO: 애플리케이션의 주요 동작이나 이벤트, 요청 처리 정보를 포함하여 스프링 부트에서는 디폴트로 INFO 레벨부터 보인다.

WARN: 경고 메시지를 기록하며, 서비스 운영 자체에는 영향이 없지만, 주의가 필요한 부분에 들어간다.

ERROR: 가장 심각한 단계이다. 즉시 조치를 취해야 하는 수준의 레벨이라고 한다.

사실 개인적으로 ExceptionHandler에서 처리하는 로깅은 어느 레벨에서 처리해야 할지 고민인데...

개인적으로 클라이언트와 계속 개발하는 단계에서는 ERROR로 핸들링해야 어떤 상황에서 오류가 발생했는지 클라이언트 개발자에게 전해주기 좋을 것 같아서 ExceptionHandler의 로깅 레벨을 ERROR로 설정하였다.

 

@ControllerAdvice
public class ControllerExceptionHandler {

    private final Logger log = LoggerFactory.getLogger(getClass());

    @ExceptionHandler(AuthenticationException.class)
    public ResponseEntity<Void> handlerAuthenticationException(AuthenticationException e) {
        log.error(e.getMessage(), e);
        return ResponseEntity.status(HttpStatus.UNAUTHORIZED).build();
    }

    @ExceptionHandler(CartItemException.IllegalMember.class)
    public ResponseEntity<Void> handleException(CartItemException.IllegalMember e) {
        log.error(e.getMessage(), e);
        return ResponseEntity.status(HttpStatus.FORBIDDEN).build();
    }

    @ExceptionHandler(Exception.class)
    public ResponseEntity<Void> exception(Exception e) {
        log.error(e.getMessage(), e);
        return ResponseEntity.status(HttpStatus.BAD_REQUEST).build();
    }
}

그래서 우선, 발생할 수 있는 모든 예외 상황에 대해서 log.error로 로깅 처리를 진행해주었다.

 

로그백을 활용해서 내가 하고 싶은 내용은 다음과 같다.

1. 기본적으로 info 하위 레벨의 로그는 console에 출력하기

2. ⭐️ 이때, error 레벨의 로그는 콘솔 및 별도의 파일에 함께 출력하기

3. error 레벨의 로그는 날짜별로 관리하기

 

---

 

🌱 Logback 분석하기

천천히 따라해보자.

src/resources 하위에 logback-spring.xml이라는 파일을 생성한다.

<configuration>
  <property resource="logback-variables.properties"/>

  <timestamp key="ToDay" datePattern="yyyy-MM-dd"/>

  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>
        ${LOG_PATTERN}
      </Pattern>
    </layout>
  </appender>

  <appender name="FILE" 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}/${ToDay}/${LOG_FILE_NAME}.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
      <fileNamePattern>
        ${LOG_PATH}/%d{yyyy-MM-dd}/${LOG_FILE_NAME}_%i.log
      </fileNamePattern>
      <maxFileSize>10MB</maxFileSize>
      <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>${LOG_PATTERN}</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="FILE"/>
    <appender-ref ref="CONSOLE"/>
  </root>

</configuration>

그리고, logback-variables.properties라는 파일을 생성한다.

LOG_PATH=./logs
LOG_FILE_NAME=jwp-shopping-order
LOG_PATTERN=%d{yyyy-MM-dd HH:mm:ss.SSS} [%level] [%thread] [%logger{36}] - %msg%n

전역적으로 관리하면 좋을 것 같은 부분에 대해 변수로 분리해두었다.

 

---

 

💬 프로퍼티와 타임스탬프 선언해주기

코드가 길기 때문에 하나씩 분리해서 차례대로 파악해보자.

먼저 프로퍼티를 불러온 다음, 3번 조건 (날짜별로 로그 관리) 구현 시 사용하기 위해 날짜 패턴을 정의해두었다.

 

---

 

💬 콘솔 출력을 위한 로깅 설정 진행하기

 

다음으로 콘솔 출력에 대한 appender를 정의하였다.

콘솔 출력 시 어떤 패턴을 사용하여 로깅을 할 것인지 정의한 것인데, 실제로 콘솔 출력과 비교해보면 다음과 같다.

발생 시간 - 로그 레벨 - 스레드 이름 - 로그 발생 주체의 이름 - 메시지

하나씩 떼어서 보니까 이해하기 쉽죠...? 😇

 

---

 

💬 파일 출력을 위한 로깅 설정 진행하기

여기는 꽤 길기 때문에 하나씩 파악해보자.

콘솔 때와 마찬가지로 appender를 정의해준다. 

이때, 우리는 2번 조건 (error 레벨의 로그는 파일로 저장)을 만족하기 위해 별도의 filter를 정의해주었다.

만약 ERROR 레벨이라면 허용, 아니라면 거절하도록 만들어준 부분이다.

 

간단하게 생각하면 정의한 fileSize와 maxHistory에 따라서 새로운 로그 파일이 생성되도록 정의하는 부분이다.

그리고, 새로운 로그파일은 _0, _1이라는 postfix와 함께 계속 생성되게 된다.

 

여기서 file과 fileNamePattern을 왜 나누었나 싶을 것이다.

우선, rollingPolicy를 사용하기 위해서는 fileNamePattern 옵션을 꼭 넣어줘야 한다. (아니면 오류남)

 

하지만, fileNamePattern만 사용하게 되면 롤링 정책에 의해 새로운 로그 파일이 생성되기 전, 첫 번째 파일을 생성할 때 위와 같이 _0라는 postfix가 붙어서 예쁘지 않다.

예쁨 주도 개발을 해야 하기 때문에 참을 수 없다. (현재 개발 수준에서는 10MB가 채워지려면 엄청난 요청이 들어와야 하기 때문에 롤링 정책이 적용되는 건 거의 보지 못했다.)

그래서 전역적으로 첫 파일이 생성될 때는 _0을 제거시키기 위해 별도의 file 태그를 통해 정의해주었다.

아무튼, file로 설정해주면 새로운 로그 파일이 생성될 때 _0을 통해 로그 파일이 생성된다.

 

---

 

💬 루트 로거에 설정해주기

All loggers are descendants of the predefined root logger

모든 로그의 경우 사전에 정의된 root logger의 자손이다.

우리가 위에서 열심히 정의한 정책을 사용하기 위해서는 루트 로거를 설정해야 된다는 것이다.

⭐️ 루트 로거의 경우 하나만 지정이 가능하며, 다중으로 설정하더라도 마지막에 선언한 것만 처리된다.

 

참고로, 이 설정을 빼면 스프링을 켤 때 아무것도 안 뜬다.

덩그러니... 나중에 다른 사람들한테 이걸로 몰래 카메라 해주고 싶다 😇

 

아무튼! 최종적으로 이렇게 진행하고 나면, 다음과 같이 에러 레벨의 로깅에 대해서만 편하게 관리할 수 있게 된다.

이건 콘솔에서 INFO 레벨 이상의 로그가 출력되는 것이고!

요렇게 파일로도 확인이 가능하게 된다 😊

 

꽤나 재밌었던 삽질이었다~~!