로그 세팅하기

지난 금요일, 애니프렌즈 프로젝트의 백엔드와 프론트엔드 API 연동을 시작했습니다. 하지만 중간 중간 api가 연동이 잘 안될 때마다 문제를 확인하기 위해 INFO, WARN 여러 레벨의 로그가 기록된 콘솔을 들여다보는 것은 번거로운 일이라는 것을 절실히 느꼈습니다.

따라서 이번 이슈를 해결함으로써 달성하고자 하는 목표는 두 가지 입니다.

• 첫째, 예외와 API 요청 로깅하기
• 둘째, 로그 레벨 별 파일로 출력하기

이를 통해 클라이언트로부터의 요청에 응답하는 과정에서 어떤 문제가 발생했는지 훨씬 쉽게 파악할 수 있을 것이라 기대합니다.

AOP 적용하기

프로젝트 초기, 예외 상황에 대해서는 AOP를 통해 로그를 남기는 것으로 계획하였습니다. 그러나 이번에 프론트엔드와 연동을 진행하며 어떤 요청이 들어왔는지에 대해 파악할 필요성을 느꼈습니다. 따라서 API 요청에 대해서도 디버그 용도의 로그를 남기기로 결정하였습니다.

AOP를 사용하는 것은 결정되었으니 우리가 사용할만한 옵션이 무엇인지 결정해야 합니다. AOP에 대한 용어 정리는 블로그 게시글을 참고해주세요.

스프링 AOP는 작성한 부가 로직이 언제 사용될지 결정할 수 있는 다양한 종류의 어드바이스를 제공합니다. 저희가 적용되길 원하는 시점은 1. 예외가 터졌을 때, 2. 클라이언트 요청이 들어왔을 때 입니다. 따라서 사용할 수 있는 어드바이스로 메서드가 예외를 던지는 경우 실행되는 @AfterReturning과 메서드 호출 전 후에 수행되는 @Around가 적절하다고 생각합니다.

각각의 AOP가 적용될 시점인 포인트 컷으로는 예외 로깅의 경우 서비스 빈들을, 클라이언트 요청 로깅의 경우 컨트롤로 빈들을 지정할 것입니다.

이러한 조건에 따라 구현한 로그 aspect는 다음과 같습니다.

@Slf4j
@Aspect
@Component
public class LogAspect {

    @Pointcut("bean(*Service)")
    private void allService(){}

    @Pointcut("bean(*Controller)")
    private void allRequest(){}

    @AfterThrowing(pointcut = "allService()", throwing = "ex")
    private void logException(JoinPoint joinPoint, RuntimeException ex) {
        String exName = ex.getClass().getSimpleName();
        String exMessage = ex.getMessage();
        String methodName = joinPoint.getSignature().toShortString();
        Object[] args = joinPoint.getArgs();
        log.warn("[Ex] {} exName=[{}] exMessage=[{}] args=[{}]",
            methodName, exName, exMessage, args);
    }

    @Around("allRequest()")
    private Object logRequest(ProceedingJoinPoint joinPoint) throws Throwable {
        long beforeRequest = System.currentTimeMillis();
        String methodName = joinPoint.getSignature().toShortString();
        Object result = joinPoint.proceed();
        long timeTaken = System.currentTimeMillis() - beforeRequest;
        log.debug("[Request] {} time=[{}ms]", methodName, timeTaken);
        return result;
    }
}

예외의 경우는 WARN 레벨로 지정해서 메서드 이름과 예외 이름, 예외 메시지, 전달된 인자들을 로그로 남깁니다. 예외가 터졌을 때 예외 메시지와 인자들을 함께 기록하여 예외의 원인이 무엇인지 조금 더 쉽게 파악할 수 있을 것입니다.

클라이언트 요청의 경우 DEBUG 레벨로 지정하여 실행된 메서드와 걸린 시간만 간단히 기록합니다. 인자들도 함께 기록하면 좋을 것 같으나 게시글 내용 또는 이미지와 같이 인자의 길이가 너무 긴 경우가 있을 거라 생각했습니다. 이 경우 오히려 로그를 확인하기 어려울 것 같아 인자는 따로 기록하지 않기로 했습니다.

실행 시 둘 모두 잘 작동하는 것을 확인할 수 있었습니다.

Logback 적용하기

스프링 부트는 properties를 통해 로그 파일 출력, 파일 이름 지정, 사이즈에 따라 새로운 파일 생성 등과 같은 로그와 관련된 여러 설정을 편리하게 관리할 수 있습니다. 그러나 레벨 별로 파일을 출력하는 것은 지원하지 않습니다. 따라서 직접 Logback 설정 파일을 생성하고 관리해야합니다.

스프링 부트 공식 문서에서는 로깅 설정을 사용하려는 경우 파일 이름에 -spring을 추가할 것을 권장하고 있습니다. 만일 기본 이름만 사용하는 경우(logback.xml) 스프링이 로그 초기화를 제어할 수 없다는 것이 이유입니다.

저희 프로젝트에서는 logback을 사용할 것입니다. 따라서 공식 문서의 권고에 따라 resources 아래에 logback-spring.xml을 추가해주었습니다.

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%kvp- %msg%n</pattern>
    </encoder>
  </appender>

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

이는 Logback 공식 문서에서 설명하는 가장 기본적인 설정입니다. 이대로 사용하는 경우 다음과 같이 상당히 밋밋한 메시지가 콘솔에 출력됩니다.

이에 따라 logback 설정은 다음 두 가지를 목표로 잡았습니다. 1. 로그 출력 형식은 스프링 부트가 제공하는 패턴을 따를 것, 2. debug, info, warn, error 레벨 별로 분리하여 파일로 출력할 것

1. 스프링 부트 로그 패턴 사용

스프링 부트의 로그 설정은 org/springframework/boot/logging/logback 패키지의 defaults.xml에 모여있습니다. 해당 파일을 <include resources=.../> 태그를 이용하여 프로젝트의 설정 파일에 포함시켜 사용할 수 있습니다.

<include resource="org/springframework/boot/logging/logback/defaults.xml"/>

이제 로그 패턴을 다음과 같이 ${CONSOLE_LOG_PATTERN}을 사용하면 스프링 부트가 정의한 패턴을 가져와서 사용할 수 있습니다.

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
  <!-- encoders are assigned the type
       ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
  <encoder>
    <pattern>${CONSOLE_LOG_PATTERN}</pattern>
    <charset>utf8</charset>
  </encoder>
</appender>

2. 로깅 레벨 별 파일 출력

로그를 파일로 출력하기 위해서는 새로운 appender를 추가해야 합니다. 일반적으로 로그를 파일로 남기는 경우 RollingFileAppender를 많이 사용한다고 합니다. 이를 사용하면 로그 파일의 사이즈, 날짜에 따른 새로운 로그 파일 생성과 시간, 크기 제한을 통해 오래된 로그 파일 삭제 설정이 가능합니다.

레벨 별로 파일을 출력하는 것은 LevelFilter를 사용할 수 있습니다. 이를 사용하면 정확히 매치하는 레벨만 선택적으로 출력할 수 있습니다.

debug 레벨의 로그 파일 출력을 위해 작성한 file appender는 다음과 같습니다.

<appender name="FILE-DEBUG" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>logs/debug.log</file>
  <encoder>
    <pattern>${FILE_LOG_PATTERN}</pattern>
  </encoder>
  <filter class="ch.qos.logback.classic.filter.LevelFilter">
    <level>DEBUG</level>
    <onMatch>ACCEPT</onMatch>
    <onMismatch>DENY</onMismatch>
  </filter>
  <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
    <fileNamePattern>logs/debug/debug-%d{yyyy-MM-dd}.log</fileNamePattern>
    <maxHistory>30</maxHistory>
    <totalSizeCap>3GB</totalSizeCap>
  </rollingPolicy>
</appender>

나머지 info, warn, error 레벨을 위한 appender 역시 파일 이름, 필터, 파일 패턴을 수정하여 추가해주었습니다.

이렇게 만든 appender를 적용하기 위해서는 <root> 블럭에 추가해야 합니다. 다음과 같이 <appender-ref /> 태그의 ref 속성에 각각의 appender name을 명시해주었습니다.

<root level="debug">
  <appender-ref ref="CONSOLE" />
  <appender-ref ref="FILE-DEBUG" />
  <appender-ref ref="FILE-INFO" />
  <appender-ref ref="FILE-WARN" />
  <appender-ref ref="FILE-ERROR" />
</root>

마지막으로 콘솔 출력에는 debug 레벨의 로그가 포함되는 것을 원치 않기에 한 가지 설정을 더 추가해줍시다. <root> 블럭은 단 하나만 존재할 수 있기 때문에 콘솔 appender만 따로 빼줄 수는 없습니다. 대신 ThresholdFilter를 사용하여 info 레벨보다 낮은 레벨의 로그는 출력되지 않도록 필터링 할 수 있습니다.

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
  <!-- encoders are assigned the type
       ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
  <encoder>
    <pattern>${CONSOLE_LOG_PATTERN}</pattern>
    <charset>utf8</charset>
  </encoder>
  <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>INFO</level>
  </filter>
</appender>

완성된 logback-spring.xml은 애니프렌즈 프로젝트 깃허브에서 확인하실 수 있습니다.

끝으로 공식 문서는 파일 이름 변경은 비교적 느리고 문제가 많기 때문에 실제 사용 사례가 아니라면 로그 파일의 최대 크기를 제한하는 SizeAndTimeBasedRollingPolicy를 사용하지 않는 것이 좋다고 설명하고 있습니다.

애니프렌즈 프로젝트도 이에 따라 하나의 파일당 최대 크기를 제한하지 않았습니다. 이는 추후 실제 서비스 상황을 경험하면서 필요한 경우 해당 정책으로 변경해 볼 생각입니다.