[2-3차 프로젝트] AOP & Slf4j를 통해 로깅 구현하기

✅ 로깅이란?

💡 프로그램 동작시 발생하는 모든 일을 기록하는 행위

모든 일?

• 서비스 동작 상태
• 장애(exception, error)

 

✅ 라이브러리

implementation "org.springframework.boot:spring-boot-starter-aop" // AOP
annotationProcessor 'org.projectlombok:lombok' // 롬복

• 롬복의 경우 @Slf4j 어노테이션을 사용하기 위해 추가하였다.
• 로깅 라이브러리의 경우 스프링부트를 생성하면 기본적으로 추가되는 logback을 사용하였다.

 

✅ 로그 전략

1️⃣ MDC 사용

• 멀티 스레드 환경에서도 로그를 구분할 수 있게 MDC를 사용하였다.

2️⃣ 로그 메시지 커스텀

• 추후 로그 관리 및 가독성을 위해 로그메시지를 적절히 커스텀 하였다.

3️⃣ 환경별로 다른 로그 수집 전략

• Spring boot 프로필 기능을 활용해 환경별로 로그를 설정
  • 개발환경
    • 루트레벨을 DEBUG
    • 콘솔을 통해서 로그가 노출
  • 운영환경
    • 루트레벨을 INFO
    • INFO, WARN, ERROR 각 레벨 및 날짜별로 나누어서 파일로 저장

4️⃣ 저장하는 로그 메시지

• 기본적으로 Spring boot, JPA등의 라이브러리 기본로그 저장
• 모든 메서드들에 대하여 로그를 남기면 로그 파일이 무거워질 것을 대비해서 Service, Controller에 대해서만 로그를 수집
• 성능 측정을 위해 메서드 시간 측정 로그도 Service, Controller단에 함께 넣었음

5️⃣ 로그 레벨

• Controller
  • HTTP Request - INFO
  • Controller 정상 종료 - INFO
  • 시간 측정 - INFO
  • GlobalExceptionHandler에 정의한 예외 - WARN
  • 그 외 예외 - ERROR
• Service
  • Service Method 호출 - INFO
  • Service Method 정상 종료 - INFO
  • 시간 측정 - INFO

 

✅ 구현 1. logback 관련 설정하기

💡해당 섹션에서는 logback 설정을 통해 로그 메시지를 커스텀하고 각 프로필별로 다르게 로그가 관리되도록 하겠다.

요구사항 정리

• 로그 메시지를 가독성 좋게 한다.
• 운영환경에서는
  • 루트레벨을 INFO로 설정
  • INFO, WARN, ERROR 각 레벨 및 날짜별로 나누어서 파일로 저장
• 개발환경에서는
  • 루트레벨을 DEBUG로 설정
  • 콘솔을 통해서 로그가 노출

 

1️⃣ logback-spring.xml

💡로그 설정에 대한 뼈대 역할을 하는 파일이라고 생각하면 된다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- Custom Highlight Converter -->
    <conversionRule conversionWord="highlight" converterClass="com.sscanner.team.global.configure.CustomHighlightConverter"/>
    <timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
    <property name ="LOG_PATTERN" value="%cyan(%d{yyyy-MM-dd HH:mm:ss.SSS}) [%thread] [traceId=%X{traceId}] %highlight(%-5level) %magenta(%logger{36}) - %msg %n" />

    <springProfile name="!prod">
        <include resource="console-appender.xml"/>

        <root level="DEBUG">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

    <springProfile name="prod">
        <include resource="file-info-appender.xml"/>
        <include resource="file-warn-appender.xml"/>
        <include resource="file-error-appender.xml"/>

        <root level="INFO">
            <appender-ref ref="FILE-INFO"/>
            <appender-ref ref="FILE-WARN"/>
            <appender-ref ref="FILE-ERROR"/>
        </root>
    </springProfile>
</configuration>

로그 레벨 별 색상 설정

로그 레벨 별로 색상을 다르게 설정하기 위해서 추가한 부분이다.

<!-- Custom Highlight Converter -->
<conversionRule conversionWord="highlight" converterClass="com.sscanner.team.global.configure.CustomHighlightConverter"/>

 

다음과 같은 Converter 클래스를 정의해서 로그 레벨별로 색깔을 다르게 지정하였다.

package com.sscanner.team.global.configure;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.pattern.color.ANSIConstants;
import ch.qos.logback.core.pattern.color.ForegroundCompositeConverterBase;

/**
 * logback-spring 로그 레벨별 색상 지정 Custom Converter Class
 */
public class CustomHighlightConverter extends ForegroundCompositeConverterBase<ILoggingEvent> {

    @Override
    protected String getForegroundColorCode(ILoggingEvent event) {
        return switch (event.getLevel().toString()) {
            case "ERROR" -> ANSIConstants.BOLD + ANSIConstants.RED_FG;
            case "WARN" -> ANSIConstants.BOLD + ANSIConstants.YELLOW_FG;
            case "INFO" -> ANSIConstants.BOLD + ANSIConstants.GREEN_FG;
            case "DEBUG" -> ANSIConstants.BOLD + ANSIConstants.BLUE_FG;
            case "TRACE" -> ANSIConstants.BLUE_FG;
            default -> ANSIConstants.DEFAULT_FG;
        };
    }

}

 

로그 메시지 커스텀

<property name ="LOG_PATTERN" value="%cyan(%d{yyyy-MM-dd HH:mm:ss.SSS}) [%thread] [traceId=%X{traceId}] %highlight(%-5level) %magenta(%logger{36}) - %msg %n" />

<시간> <스레드 ID> <MDC> <로그레벨> <클래스> - <로그메시지>
2024-10-09 22:56:15.892 [http-nio-8080-exec-4] [traceId=67f44166-9db2-4e51-a4b6-45c3e1bf58b6] INFO  c.s.t.g.c.aop.HttpLoggingAspect - HTTP Request: GET /test from IP 0:0:0:0:0:0:0:1 

 

환경별로 다르게 로그 관리

<springProfile name="!prod">
        <include resource="console-appender.xml"/>

        <root level="DEBUG">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

    <springProfile name="prod">
        <include resource="file-info-appender.xml"/>
        <include resource="file-warn-appender.xml"/>
        <include resource="file-error-appender.xml"/>

        <root level="INFO">
            <appender-ref ref="FILE-INFO"/>
            <appender-ref ref="FILE-WARN"/>
            <appender-ref ref="FILE-ERROR"/>
        </root>
    </springProfile>

• prod(운영환경)이 아닌 환경에서는 루트 로그 레벨을 DEBUG로 설정하였고 Console에 로그가 노출되도록 하였다.
• prod(운영환경)인 곳에서는 루트 로그 레벨을 INFO로 설정하였고 각 레벨 별로 로그 파일이 별도로 저장되도록 설정하였다.

 

2️⃣ 환경별로 다르게 로그 관리

개발환경에서의 로그 - console-appender.xml

ConsoleAppender를 통해 콘솔에 로그가 노출되도록 하였다.

<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>
</included>

 

운영환경에서의 로그 - file -*-appender.xml

RollingFileAppender를 통해 파일로 로그가 저장되게 하였다.

[ex - file-info-appender.xml]

<included>
    <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>${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>
</included>

 

RollingPolicy 부분이 헷갈려서 조금 더 자세히 정리해봤다.

<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>

• fileNamePattern: 백업될 로그파일의 패턴을 지정하는 부분인데 여기서 dateTime 패턴을 지정할 수 있다.
  • %d{yyyy-MM-dd}: 일단위(기본값)
• maxFileSize: /log 디렉토리에 저장한 로그 파일이 해당용량이 넘으면 그 파일은 /backup 디렉토리로 이동하고 새로운 로그 파일을 /log 디렉토리에 만든다
• maxHistory: 크게 두 가지 역할을 한다.
  • /backup/info 디렉토리의 파일이 해당 갯수 이상이면 가장 오래된 파일을 삭제한다.
  • /backup/info 디렉토리의 파일이 해당 시간이 지나면 가장 오래된 파일을 삭제한다. 이때 시간 기준은 fileNamePattern의 명시한 dateTime 패턴이다.
• totalSizeCap: /backup/info 디렉토리 파일의 총 용량이 해당 용량을 넘어가면 가장 오래된 파일을 삭제한다

 

✅ 구현2. AOP로 로그 메시지 만들기

요구사항 정리

• MDC를 사용해 멀티 스레드 환경에서도 로그를 구분할 수 있게 MDC를 사용하였다.
• 기본적으로 Spring boot, JPA등의 라이브러리 기본로그 저장
• 모든 메서드들에 대하여 로그를 남기면 로그 파일이 무거워질 것을 대비해서 Service, Controller에 대해서만 로그를 수집
• 성능 측정을 위해 메서드 시간 측정 로그도 Service, Controller단에 함께 넣었음
• 로그 레벨
  • Controller
    • HTTP Request - INFO
    • Controller 정상 종료 - INFO
    • 시간 측정 - INFO
    • GlobalExceptionHandler에 정의한 예외 - WARN
    • 그 외 예외 - ERROR
  • Service
    • Service Method 호출 - INFO
    • Service Method 정상 종료 - INFO
    • 시간 측정 - INFO

 

1️⃣ Controller 로그 AOP

@Component
@Aspect
@Slf4j
public class HttpLoggingAspect {

    private long startTime;

    // Controller의 모든 메서드에 대해 적용
    @Pointcut("execution(* com.sscanner.team..controller.*.*(..))")
    public void pointCut() {}

    @Before("pointCut()")
    public void logHttpRequest(JoinPoint joinPoint) {
        MDC.put("traceId", UUID.randomUUID().toString()); // 멀티 스레드 환경에서도 로그를 구분할 수 있게 해줌
        startTime = System.currentTimeMillis();
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();
        log.info("HTTP Request: {} {} from IP {}", request.getMethod(), request.getRequestURI(), request.getRemoteAddr());
    }

    // 메서드 호출 후 정상적으로 반환된 경우 로그 남기기
    @AfterReturning(pointcut = "pointCut()", returning = "result")
    public void logAfterReturning(JoinPoint joinPoint, Object result) {
        log.info("Exiting Controller: {} with result {}", joinPoint.getSignature(), result);
    }

    // 예외 발생 시 로그 남기기
    @AfterThrowing(pointcut = "pointCut()", throwing = "ex")
    public void logAfterThrowing(JoinPoint joinPoint, Throwable ex) {
        if(ex instanceof BadRequestException || ex instanceof DuplicateException || ex instanceof MethodArgumentNotValidException) return;
        log.error("Exception in Controller: {} with arguments {}. Exception: {}", joinPoint.getSignature(), Arrays.toString(joinPoint.getArgs()), ex.getMessage(), ex);
    }

    // 완전히 종료된후 메서드 실행시간 측정하기
    @After("pointCut()")
    public void logAfter(JoinPoint joinPoint) {
        long executionTime = System.currentTimeMillis() - startTime;
        log.info("{} Execution time: {}ms", joinPoint.getSignature(), executionTime);
        MDC.clear();
    }
}

 

2️⃣ Service 로그 AOP

@Component
@Aspect
@Slf4j
public class ServiceLogAspect {

    private long startTime;

    // service의 모든 메서드에 대해 적용
    @Pointcut("execution(* com.sscanner.team..service.*.*(..))")
    public void pointCut() {}

    // 메서드 호출 전 로그 남기기
    @Before("pointCut()")
    public void logBefore(JoinPoint joinPoint) {
        startTime = System.currentTimeMillis();
        log.info("Entering Service: {} with arguments {}", joinPoint.getSignature(), Arrays.toString(joinPoint.getArgs()));
    }

    // 메서드 호출 후 정상적으로 반환된 경우 로그 남기기
    @AfterReturning(pointcut = "pointCut()", returning = "result")
    public void logAfterReturning(JoinPoint joinPoint, Object result) {
        log.info("Exiting Service: {} with result {}", joinPoint.getSignature(), result);
    }

    // 완전히 종료된후 메서드 실행시간 측정하기
    @After("pointCut()")
    public void logAfter(JoinPoint joinPoint) {
        long executionTime = System.currentTimeMillis() - startTime;
        log.info("{} Execution time: {}ms", joinPoint.getSignature(), executionTime);
    }
}

• 서비스 계층의 메서드는 컨트롤러를 통해서만 호출되기 때문에 예외에 대한 AOP는 설정하지 않았다.
• MDC 또한 같은 이유로 서비스에선 사용하지 않았다.

 

✅ 테스트

다음과 같은 테스트 컨트롤러, 서비스를 만들어보았다.

// 컨트롤러
@GetMapping("/test")
public String test() {
    testService.testLogic();
    return "test";
}

// 서비스
public void testLogic() {
    System.out.println("TestService.testLogic");
}

개발 환경

 

운영 환경

 

✅ 개선 사항

1. 로그 파일들은 Docker Image 내부에 저장된다. 배포할 때마다 새롭게 빌드가 이루어지기 때문에 배포할 때마다 기존 로그 파일이 날아간다.

→ 별도의 저장 시스템 필요

 

2. 로그 파일을 보기가 힘들다. 직접 이미지 내부에 들어가서 명령어를 입력해 찾아야 한다. 파일이 길어질수록 원하는 부분을 찾기가 힘들다

→ 시각화해주는 툴 필요

 

이러한 부분을 해결하기 위해 ELK, PLG 스택 등 중앙 집중화 로깅 시스템을 사용할 생각이다.

 

✅ 참고 자료

[Java] MDC 를 사용한 로그(Log)추적하기

[Logging] SLF4J란?

[Logging] Logback이란?