[Logging] Logback을 이용한 기본적인 로깅하기

---

들어가면서

 

현재 진행중인 팀 프로젝트 하루스터디 서비스는 배포가 완료된 상태입니다. 배포 완료의 기쁨을 느꼈던 것도 잠시, 저희는 실제 배포 환경에서 서비스를 운영하면서 마주치는 버그와 이슈 상황들을 바로 마주하게 되었습니다. 로컬 환경에서라면 인텔리제이의 debug 기능을 활용하거나 정말 단순하게는 System.out을 통해 원하는 값을 직접 출력 해볼 수도 있을 것입니다.

 

하지만 현재 하루스터디 서비스는 배포 서버에 이미 배포가 되어 있는 상태라서 기존 방식으로는 버그와 이슈 상황들에 대한 원인 파악이 쉽지 않았습니다. 따라서 이를 해결하기 위해 로깅 기능을 구현해서 도입하기로 결정했습니다. 본 포스팅은 팀 로깅 작업을 진행하기 전 개인적으로 진행한 학습 내용을 정리하기 위한 것임을 밝힙니다. 

 

 

 

---

SLF4J와 Logback

 

스프링 환경에서 로깅을 구현한다고 하면 바로 접할 수 있는 2개의 키워드입니다. 바로 SLF4J와 Logback인데요, 하나씩 간단하게 개념을 정리해보았습니다.

 

• SLF4J(Simple Logging Facade For Java)
  • 다양한 로깅 프레임워크들을 한단계 추상화한 추상 로깅 프레임워크입니다. 실제로 사용할 때는 사용자가 원하는 구현체를 선택해서 사용하게 됩니다.
• Logback
  • SLF4J 인터페이스를 구현한 실제 구현체 프레임워크입니다.
  • Log4J라는 구현체 프레임워크를 전신으로 만들어졌습니다.
  • 스프링 부트에서 기본적으로 사용하는 로깅 프레임워크입니다.

 

해당 개념들을 깊게 다루려고 하면 생각보다 방대한 내용들이 다뤄져야 하기에 이 정도로만 간단하게 개념만 짚고 넘어가도록 하겠습니다. 깊은 내용은 따로 정리해보도록 하겠습니다.

 

 

 

---

무엇을 로깅해야 할까?

현재 진행중인 프로젝트 팀에서 마주한 문제상황은 "실제 운영중인 서비스에서 발생하는 버그나 예외상황에 대한 원인 파악이 힘들다"는 것입니다. 그러면 이러한 문제상황을 해결하려면 어떠한 정보들이 로깅되어야 할지에 대해 먼저 생각해보았습니다. 개인적으로 서비스에서 발생한 버그와 예외상황을 트러블 슈팅하기 위해 필요한 정보들을 정리해본 결과는 다음과 같았습니다.

 

• 기본적인 스프링 콘솔 출력 로그 메세지
• 서비스 요청 / 응답 HTTP 메세지

 

기본적인 스프링 콘솔 출력 로그 메세지는 스프링 레벨에서 발생한 예외 상황들을 파악하기 위해서 필수적으로 확인해봐야 하는 것 중 하나입니다. 스프링 콘솔 출력 메세지는 다음과 같이 크게 6단계의 레벨을 가지고 로깅됩니다.

• Fatal : 프로그램이 종료될 정도의 치명적인 예외상황을 나타냅니다. 보통 프로그램이 종료되면서 로깅 자체가 안되는 경우가 많기에 거의 사용하지 않습니다.
•  Error : 개발자가 의도하지 않은 예외, 즉 예상치 못한 예외상황에 대한 로깅 레벨입니다. 하지만 프로그램이 종료되지는 않는 정도의 수준입니다.
• Warn : 예외상황은 아니지만 이후 예외로 발전할 수 있는 가능성을 지닌 상황들에 대한 로깅 레벨입니다.
• Info : 개발자가 의도한 예외 상황에 대한 로깅 레벨 + 일반적으로 요구사항에 따른 서버의 동작을 출력해야 할 때 사용하는 로깅 레벨입니다.
• Debug : Info 보다 더 상세한 정보들을 명시하는 로깅 레벨입니다. 보통 프로덕션 환경이 아니라 개발 환경에서 로깅할 때 사용합니다.
• Trace : Debug 로깅 레벨보다 더 자세한 정보들을 명시하는 로깅 레벨로 개발 환경에서 디버깅을 진행할 때 사용합니다.

팀 서비스 트러블 슈팅을 위해서는 Info ~ Error 레벨 정도까지의 콘솔 출력 메세지가 필요하다고 판단했습니다. 예상치 못하게 발생한 예외에 대한 Stack Trace 정보는 Error 레벨로 콘솔에 함께 출력시킬 수 있기 때문입니다. 그 외 Info 레벨과 Warn 레벨의 로그들도 상황에 따라 추가적으로 필요해질 수도 있겠다는 판단을 했습니다.

 

 

서비스 요청 / 응답 HTTP 메세지는 클라이언트로부터 정상적인 요청이 들어왔는지 서버에서 응답이 정상적으로 처리되어 나가는지를 확인하는데 필수적입니다. 따라서 각 요청 / 응답 HTTP 메세지에 대해 필요한 데이터들을 로깅할 수 있어야 한다고 판단했습니다.

 

 

 

---

어떻게 로깅해야 할까?

앞에서 어떤 데이터들을 로깅해야 하는지를 결정했으니 이제 실제로 해당 데이터들을 로깅하기 위해 설정을 진행했습니다. 현재 저희 서비스는 스프링 부트 환경에서 운영되고 있으므로 기본으로 채택되고 있는 Logback을 이용하여 로깅을 진행하게 될 것입니다. 

 

Logback을 사용하기 위해서는 logback-spring.xml 파일에서 사용하고자 하는 로거에 대한 여러가지 설정을 해줘야 합니다. 다음은 해당 포스팅을 작성하는데 사용된 logback-spring.xml 파일 본문입니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
  <property name="CONSOLE_LOG_PATTERN" value="%green(%d{yyyy-MM-dd HH:mm:ss.SSS}) %magenta([%thread]) %clr(%5level) %cyan(%logger) - %yellow(%msg%n)" /> <!-- 해당 패턴 네이밍으로 현재 콘솔 로그가 기록됨 -->
  <property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %5level %logger - %msg%n" /> <!-- 해당 패턴 네이밍으로 현재 파일 로그가 기록됨 -->

  <include resource="console-appender.xml" />
  <include resource="default-appender.xml" />
  <include resource="error-appender.xml" />
  <include resource="http-appender.xml" />

  <logger name="HaruStudyExceptionLogger" level="WARN" additivity="false">
    <appender-ref ref="ERROR"/> <!-- error-appender.xml 설정의 appender 사용 -->
  </logger>

  <logger name="HaruStudyHttpLogger" level="INFO" additivity="false">
    <appender-ref ref="HTTP"/> <!-- http-appender.xml 설정의 appender 사용 -->
  </logger>

  <root level="INFO"> <!-- 전체 프로젝트의 로그 레벨을 설정 -->
    <!-- 여기에 추가되는 Appender들은 root에 설정된 level 로깅을 각자 설정에 맞게 자동으로 수행해준다.   -->
    <appender-ref ref="CONSOLE"/> <!-- 사용하고자 하는 appender 등록 -->
    <appender-ref ref="DEFAULT"/>
  </root>
</configuration>

 

코드에 대한 전반적인 설명은 주석으로 달아두었습니다. logback-spring.xml의 전체적인 흐름을 보면 logger를 정의할 때 level과  additivity를 지정해줍니다. level은 해당 로거에서 출력할 로그의 하한 레벨을 설정하고 additivity는 로깅을 수행하고 상위 로거로도 재요청을 할지 여부를 결정합니다. 그리고 로거마다 어떤 appender를 사용할 지 설정해줍니다. 여기에서 appender는 로그 메세지가 출력될 대상을 설정하는 곳입니다. 따라서 로거마다 어디에 로깅을 할 지를 직접 지정해줄 수 있습니다. 

 

appender.xml 코드로 들어가기 전에 짚고 넘어가면 좋을 부분이 있습니다. 바로 root 로거와 다른 로거들의 관계입니다. root 로거는 모든 로거들을 기준으로 최상위 로거입니다. 하위 로거들을 따로 사용하는 경우, 앞서 설명했던 additivity 옵션의 기본값은 true 입니다. 즉 모든 하위 로거들의 로깅 이후 root 로거에서 중복으로 로깅을 수행한다는 것입니다. 해당 포스팅에서는 이를 방지하기 위해 하위 로거들마다 additivity 옵션을 false로 주었음을 확인할 수 있습니다. 

 

 

<!-- console-appender.xml -->

<included>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>${CONSOLE_LOG_PATTERN}</pattern> <!-- 해당 패턴 네이밍으로 현재 로그가 기록됨 -->
    </layout>
  </appender>
</included>

Console에 출력되는 로깅을 어디에 저장할지 설정하는 console-appender.xml 파일입니다. appender의 옵션으로 class를 ConsoleAppender로 지정해주고 있는 것을 확인할 수 있습니다. 이는 logback.core 라이브러리에 미리 구현되어 있는 appender 클래스를 사용해 콘솔에 로깅을 출력하겠다는 의미입니다. 또한 내부에서 PatternLayout을 사용해서 logback-spring.xml 에 정의되어 있는 ${CONSOLE_LOG_PATTERN} 형식에 맞춰서 로깅하겠다는 의미입니다. 해당 appender를 root 로거에 추가해주지 않으면 서버 구동 시 출력되던 console 로그가 출력되지 않습니다. 

 

 

<!-- default-appender.xml-->

<included>
  <appender name="DEFAULT" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>INFO</level>
      <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
      <onMismatch>DENY</onMismatch> <!-- 다른 수준의 레벨은 기록하지 않는다.(상위 레벨도 기록 안함), 상위 수준의 레벨에 대한 기록을 원하면 ACCEPT 로 하면 기록된다. -->
    </filter> <!-- 레벨별 필터링이 필요없을 경우 filter class 관련된 부분을 삭제하면 됨-->
    <encoder>
      <pattern>${FILE_LOG_PATTERN}</pattern> <!-- 해당 패턴 네이밍으로 현재 로그가 기록됨 -->
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>./logs/default/default-logs.%d{yyyy-MM-dd}.%i.log</fileNamePattern> <!-- 해당 패턴 네이밍으로 이전 파일이 기록됨, %i는 rolling index -->
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <!-- 정해둔 시간에 맞춰 사이즈에 알맞게 로깅을 하겠다는 정책 -->
        <maxFileSize>20MB</maxFileSize> <!-- 한 파일의 최대 용량 -->
      </timeBasedFileNamingAndTriggeringPolicy>
      <maxHistory>30</maxHistory> <!-- 한 파일의 최대 저장 기한 -->
      <totalSizeCap>100MB</totalSizeCap> <!-- 전체 로깅파일의 크기를 제어한다. 제한 크기를 초과하면 가장 오래된 파일을 삭제 -->
    </rollingPolicy>
  </appender>
</included>

앞에서 설명한 console-appender.xml과 달라진 점은 filter와 rollingPolicy가 추가되었다는 것입니다. filter를 통해서 INFO 레벨의 로그만 따로 로깅을 하겠다는 설정을 해주었습니다. rollingPolicy는 로깅된 파일을 어떤 기준으로 관리할 것인지를 설정해주는 옵션입니다. 주로 파일의 크기 또는 시간에 따라 주기적으로 분리하고 관리할 수 있습니다. 

 

default-appender는 기존 콘솔창에 출력되던 로그 중 INFO 레벨의 로그만 따로 관리하기 위한 appender입니다.

 

 

<!-- error-appender.xml -->

<included>
  <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>WARN</level>
      <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
      <onMismatch>ACCEPT</onMismatch> <!-- 다른 수준의 레벨은 기록하지 않는다.(상위 레벨도 기록 안함), 상위 수준의 레벨에 대한 기록을 원하면 ACCEPT 로 하면 기록된다. -->
    </filter> <!-- 레벨별 필터링이 필요없을 경우 filter class 관련된 부분을 삭제하면 됨-->
    <encoder>
      <pattern>${FILE_LOG_PATTERN}</pattern> <!-- 해당 패턴 네이밍으로 현재 로그가 기록됨 -->
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>./logs/warn-error/warn-error-logs.%d{yyyy-MM-dd}.%i.log</fileNamePattern> <!-- 해당 패턴 네이밍으로 이전 파일이 기록됨, %i는 rolling index -->
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <!-- 정해둔 시간에 맞춰 사이즈에 알맞게 로깅을 하겠다는 정책 -->
        <maxFileSize>5MB</maxFileSize> <!-- 한 파일의 최대 용량 -->
      </timeBasedFileNamingAndTriggeringPolicy>
      <maxHistory>30</maxHistory> <!-- 한 파일의 최대 저장 기한 -->
      <totalSizeCap>20MB</totalSizeCap> <!-- 전체 로깅파일의 크기를 제어한다. 제한 크기를 초과하면 가장 오래된 파일을 삭제 -->
    </rollingPolicy>
  </appender>
</included>

전체적인 틀은 앞에서 설명한 default-appender와 동일합니다. error-appender는 실질적인 트러블 슈팅에 필요한 ERROR 레벨과 WARN 레벨의 로그들만 따로 관리하기 위한 appender 입니다. 

 

 

<!-- http-appender.xml -->

<included>
  <appender name="HTTP" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>INFO</level>
      <onMatch>ACCEPT</onMatch> <!-- 해당 레벨만 기록한다. -->
      <onMismatch>DENY</onMismatch> <!-- 다른 수준의 레벨은 기록하지 않는다.(상위 레벨도 기록 안함), 상위 수준의 레벨에 대한 기록을 원하면 ACCEPT 로 하면 기록된다. -->
    </filter> <!-- 레벨별 필터링이 필요없을 경우 filter class 관련된 부분을 삭제하면 됨-->
    <encoder>
      <pattern>${FILE_LOG_PATTERN}</pattern> <!-- 해당 패턴 네이밍으로 현재 로그가 기록됨 -->
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>./logs/http/requestResponse-logs.%d{yyyy-MM-dd}.%i.log</fileNamePattern> <!-- 해당 패턴 네이밍으로 이전 파일이 기록됨, %i는 rolling index -->
      <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <!-- 정해둔 시간에 맞춰 사이즈에 알맞게 로깅을 하겠다는 정책 -->
        <maxFileSize>20MB</maxFileSize> <!-- 한 파일의 최대 용량 -->
      </timeBasedFileNamingAndTriggeringPolicy>
      <maxHistory>30</maxHistory> <!-- 한 파일의 최대 저장 기한 -->
      <totalSizeCap>100MB</totalSizeCap> <!-- 전체 로깅파일의 크기를 제어한다. 제한 크기를 초과하면 가장 오래된 파일을 삭제 -->
    </rollingPolicy>
  </appender>
</included>

전체적인 틀은 앞에서 설명한 default-appender와 동일합니다. http-appender는 HTTP 요청 / 응답 메세지를 INFO 레벨의 로그로 관리하기 위한 appender입니다. 현재는 default-appender를 사용하는 로거와 다른 점이 없습니다. 원래는 httpRequest와 httpResponse를 가져와서 따로 로깅을 해주기 위함이었으나 추가적인 설정을 해주기 위해 시간이 더 필요할 것 같아 해당 내용은 후속 포스팅으로 정리해보려 합니다. 

 

 

 

---

로거 적용하기(feat. lombok)

 

앞에서 소개한 logback-spring.xml을 다시 보면 결과적으로 선언된 로거는 다음과 같이 총 3개입니다.

• root
• HaruStudyExceptionLogger
• HaruStudyHttpLogger

그리고 현재 하루스터디 프로젝트에서는 lombok을 사용하고 있기에 이를 활용해서 로거를 사용하는 방법으로 적용을 해봤습니다. 3개의 로거를 직접 사용하기 위해 작성한 코드 다음과 같습니다. 

 

 

root

@Slf4j
@RestController
public class logController {

    @Autowired
    private LogService logService;

    @GetMapping("/api/log")
    public String logTest(){

        String name = "haruharu";

        int i = 0;
        while(i<5){
            //  {}에는 파라미터 값이 들어갑니다
            log.error("error log={}",name);
            log.warn("warn log={}",name);
            log.info("info log={}",name);
            log.debug("debug log={}",name);
            log.trace("trace log={}",name);
            i++;
        }

        return "ok";
    }
}

lombok에는 @Slf4j 어노테이션을 사용하여 쉽게 로거를 사용할 수 있도록 도와줍니다. @Slf4j 어노테이션에 아무런 옵션을 주지 않고 사용하면 다음과 같은 코드가 컴파일 시점에 추가됩니다.

private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger(LogController.class);

해당 로거는 root 로거를 자동으로 사용합니다. root 로거에는 console과 default appender가 추가되어 있기에 콘솔과 지정된 루트에 로깅을 하게 됩니다.

 

 

 

실행결과

 

console-appender에 따른 콘솔 출력 결과입니다.

root 로거의 하한 로깅 레벨이 INFO로 되어 있어 그 이상만 로깅되어 콘솔에 출력됩니다.

 

default-appender에 따른 로깅파일 생성 결과입니다. 콘솔과 다르게 정확히 INFO 레벨인 로그만 기록되고 있음을 확인할 수 있습니다.

 

 

 

HaruStudyExceptionLogger

@Slf4j(topic = "HaruStudyExceptionLogger")
@RestControllerAdvice
public class GlobalExceptionAdvice {

    @ExceptionHandler(CustomException.class)
    public ResponseEntity<Void> customExceptionHandler(CustomException error) {
        log.error("MESSAGE: " + error.getMessage());
        log.error("StackTrace: " + error);
        return ResponseEntity.badRequest().build();
    }

    @ExceptionHandler(IllegalArgumentException.class)
    public ResponseEntity<Void> illegalArgumentExceptionHandler(IllegalArgumentException error) {
        log.error("MESSAGE: " + error.getMessage());
        log.error("StackTrace: ", error);
        return ResponseEntity.badRequest().build();
    }
}

이번엔 예외처리와 관련된 로깅을 위한 HaruStudyExceptionLogger입니다. @Slf4j를 사용할 때 topic 옵션을 주게되면 다음과 같은 코드가 컴파일 시점에 추가됩니다.

private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger("HaruStudyExceptionLogger");

 

HaruStudyExceptionLogger는 WARN 레벨 이상의 로그를 따로 관리하는 설정을 해줬었고 error-appender.xml 설정에 따라 로깅을 진행하게 됩니다.

 

 

실행결과

해당 로그파일은 CustomException과 IllegalArgumentException이 각각 연달아서 발생시킨 뒤의 상태입니다. customException을 로깅했을 때는 간단한 stacktrace를 출력하였고 IllegalArgumentException을 로깅했을 때는 상세한 stacktrace를 출력하였습니다. log.error 메서드의 몇번째 인자로 error 객체를 넘기느냐에 따라 결과 이미지와 같이 어느 정도로 stacktrace를 출력할지 결정할 수 있습니다.

 

 

 

HaruStudyHttpLogger

@Slf4j(topic = "HaruStudyHttpLogger")
public class HttpLoggingInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
            Object handler) throws Exception {
        log.info(request.getMethod());
        log.info("requestURI : " + request.getRequestURI());
        log.info(request.getQueryString());
        log.info(((HandlerMethod) handler).toString());
        return true;
    }
}

앞에서 설명한것과 같이 HaruStudyHttpLogger를 사용할 수 있도록 다음과 같은 코드가 삽입됩니다.

private static final org.slf4j.Logger log = org.slf4j.LoggerFactory.getLogger("HaruStudyHttpLogger");

 

서비스의 HTTP 요청 메세지를 interceptor에서 로깅해주고 있습니다. HTTP 요청 메세지의 정보들이 http-appender.xml 설정에 따라 INFO 레벨의 로그로 저장됩니다.

 

 

실행결과

 

추가내용

HTTP 요청 / 응답 메세지 로깅을 Filter가 아니라 Interceptor에 구현한 이유

=> Filter 에서는 기본적으로 ServletRequest / ServletResponse를 인자로 받는 메서드를 오버라이딩해서 사용하지만 Interceptor는 HttpServletRequest / HttpServletResponse를 인자로 받는 메서드를 오버라이딩한다. 현재 우리가 로깅해야 할 내용은 HTTP 요청 / 응답 메세지에 담겨있는 내용으로 HttpServletRequest / HttpServletResponse 가 필요했다. 또한 들어온 요청이 어떤 Controller(handler)가 호출되었는지도 확인해서 로깅이 가능했기 때문에 Interceptor를 선택했다.

 

 

 

---

더 알아볼 것

 

이렇게 logback을 이용한 기본적인 로깅 기능에 대해 학습해봤습니다. 다만 아쉬운 점은 시간 문제로 HTTP 요청 / 응답 메세지 body의 로깅을 아직 해보지 못했다는 것입니다. body 데이터 로깅 시 json 양식으로 보기 좋게 넣는 것을 해보고 싶었으나 생각보다 고려해야할 점이 많았습니다. 해당 부분은 다음에 학습하고 후속 포스팅에서 작성해보겠습니다!