[feat] #310 - log4j2를 이용한 AOP 로깅방식 도입 완료

[hoonyworld]

Related issue 🛠

• closes [feat] Log4j2를 이용한 AOP 로깅 도입 #310

Work Description ✏️

log4j2 설명

비동기(AsyncLogger, AsyncAppender)적으로 로깅할 때, 각 로깅 프레임워크의 초당 메시지 처리량(msg/sec)을 측정한 그래프입니다

각 색상의 막대 그래프:
파란색 (Log4j2: Loggers all async) → Log4j2에서 모든 Logger를 비동기(AsyncLogger)로 설정한 경우
빨간색 (Log4j2: Loggers mixed sync/async) → Log4j2에서 일부 로거는 동기(SyncLogger), 일부는 비동기(AsyncLogger)
노란색 (Log4j2: Async Appender) → Log4j2에서 AsyncAppender만 사용
보라색 (Log4j1: Async Appender) → Log4j1에서 AsyncAppender 사용
연두색 (Logback: Async Appender) → Logback에서 AsyncAppender 사용

비동기(AsyncLogger, AsyncAppender) 없이 동기적으로 로깅할 때, 각 로깅 프레임워크의 초당 메시지 처리량(msg/sec)을 측정한 그래프입니다
Log4j2(파란색, 하늘색)가 Logback (주황색)보다 동기 상황에서도 성능이 좋은것을 확인할 수 있습니다.

결론

• 동기/비동기 상황 모두 고부하 환경에서 Log4j2가 Logback에 비해 압도적으로 로깅 처리량이 높은 것을 확인할 수 있습니다.
• 따라서 로깅 구현체로 현재 스프링부트에 기본으로 내장된 logback 대신 log4j2가 적합할 것으로 판단하여 log4j2를 도입하게 되었습니다.

log4j2-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="INFO">
    <!-- Properties 태그 추가 -->
    <Properties>
        <Property name="LOG_PATTERN">
            %style{%d{yyyy-MM-dd HH:mm:ss,SSS}}{blue} %highlight{[%-5p]}{FATAL=bg_red, ERROR=red, WARN=yellow, INFO=green, DEBUG=bright_blue, TRACE=cyan} [%t] %style{[%c{1}.%M():%L]}{BRIGHT_BLACK} - %m%n
        </Property>
    </Properties>

    <!-- 콘솔 출력 설정 -->
    <Appenders>
        <Console name="Console_Appender" target="SYSTEM_OUT">
            <PatternLayout pattern="${LOG_PATTERN}"/>
        </Console>
    </Appenders>

    <!-- 환경별 로깅 설정 -->
    <Loggers>
        <springProfile name="local">
            <Root level="INFO">
                <AppenderRef ref="Console_Appender"/>
            </Root>
        </springProfile>

        <springProfile name="dev">
            <Root level="INFO">
                <AppenderRef ref="Console_Appender"/>
            </Root>
        </springProfile>

        <springProfile name="prod">
            <Root level="INFO">
                <AppenderRef ref="Console_Appender"/>
            </Root>
        </springProfile>

        <springProfile name="test">
            <Root level="INFO">
                <AppenderRef ref="Console_Appender"/>
            </Root>
        </springProfile>
    </Loggers>
</Configuration>

• 현재 설정한 log4j2-spirng.xml 구현 코드입니다.
• 모든 profile(local, dev, prod, test)에서 루트 레벨을 info로하여 로깅을 할 수 있도록 설정하였습니다.
• 또한, 비동기 세팅 없이(cc. AsyncLogger, AsyncAppender) 동기적으로 로깅을 하도록 설정을 해둔 상황입니다.
• 그 이유는 AsyncLogger, AsyncAppender와 같은 비동기 방식은 다음과 같은 문제점이 존재하기 때문입니다.

비동기 로깅의 단점

1. 로그 유실 가능성 (Lost Logs)

• 애플리케이션이 비정상 종료되거나 예기치 않은 시스템 장애가 발생하면, 큐에 쌓인 로그가 저장되지 않고 유실될 위험이 있습니다.
• AsyncLogger / AsyncAppender 모두 별도 쓰레드에서 로그를 처리하므로, 로그가 실제 파일에 기록되기 전에 종료되면 로그 손실이 발생할 수 있습니다.
• 해결 방법으로는 shutdownHook="true" 설정 추가하여 종료 전에 큐를 비우고 로그 기록 강제 수행하거나, queueFullPolicy="Discard" 대신 queueFullPolicy="Block"으로 설정해 버퍼 초과 시 대기하도록 설정할 수 있습니다.

2. 로깅 실패 감지 어려움 (Error Handling Challenge)

• 동기 로깅은 logger.info("로그 기록") 실행 시점에 바로 로그가 기록되지만, 비동기 로깅은 로그가 큐에 저장된 후 별도 쓰레드에서 처리되므로, 로깅 실패가 발생해도 애플리케이션 코드에서 이를 즉시 감지할 수 없습니다.
• 에를 들어, 디스크 공간 부족, 네트워크 장애, 파일 시스템 문제 등으로 로그 기록이 실패해도 logger.info() 호출 자체는 성공한 것으로 처리되는 상황이 있습니다.
• 해결 방법으로는 queueFullPolicy="enforce"를 설정하여, 큐가 가득 찼을 때 예외를 발생시켜 애플리케이션이 감지하도록 하고, 로깅 중 예외가 발생하면 별도의 ErrorLogger를 사용하여 실패 로그를 기록하도록 설정하는 방법이 있습니다.

결론

• 저는 비즈니스 로직 로깅에서 로그 유실이 발생하는 것이 치명적인 문제라고 판단했습니다.
• 이에 대한 해결책을 조사한 결과, 중요한 로그는 Sync Logger를 사용하고, 그렇지 않은 로그는 Async Logger를 혼합하여 운영하는 방식이 효과적인 대안으로 보였습니다.
• 따라서, 해당 방식을 도입하기 전에 전체적으로 동기로깅을 적용했을 때, dev서버에 부하 테스트를 통해 로깅 성능을 측정하고, 최적의 설정을 찾고자 합니다.

AOP 도입

• 애플리케이션 전반에 걸친 공통 관심 사항(로깅, 트랜잭션 관리, 실행 시간 측정 등)을 AOP(Aspect Oriented Programming)를 이용해 분리하여 관리하기 위해 도입하게 되었습니다.

Pointcuts.java

package com.beat.global.common.aop;

import org.aspectj.lang.annotation.Pointcut;

public class Pointcuts {
	@Pointcut("execution(* com.beat..*Controller.*(..))")
	public void allController() {}

	@Pointcut("execution(* com.beat..*Service.*(..)) || execution(* com.beat..*UseCase.*(..)) || execution(* com.beat..*Facade.*(..))")
	public void allService() {}

	@Pointcut("execution(* com.beat..*(..))" +
		" && !within(com.beat.global..*)")
	public void allApplicationLogic() {}
}

• 해당 클래스는 AOP가 적용될 대상(포인트컷, Pointcut)을 정의한 것으로, 각각의 메서드는 특정 패키지 내의 클래스를 대상으로 AOP를 적용할 수 있도록 구현하였습니다.
  • allController(): com.beat 패키지 아래의 모든 Controller 클래스의 메서드에 AOP 적용
  • allService(): Service, UseCase, Facade 클래스를 포함하는 비즈니스 로직 계층에 AOP 적용
  • allApplicationLogic(): com.beat.global 패키지를 제외한 모든 클래스의 메서드에 AOP 적용 (이 부분은 추후 변동성 있음)

ExecutionTimeLoggerAspect.java

@Aspect
@Order(0)
@Component
public class ExecutionTimeLoggerAspect {
...
...
}

• 해당 클래스는 애플리케이션의 성능을 모니터링하기 위해 실행 시간을 측정 및 로깅할 수 있도록 구현하였습니다.
• @order(0)을 적용하여 AOP 체인의 가장 바깥쪽에서 실행되도록 설정하였으며, 트랜잭션, 서비스 로깅 등의 다른 AOP가 적용되기 전에 실행됩니다.
• @around 어노테이션을 사용하여 메서드 실행 전후로 System.currentTimeMillis()를 이용해 실행 시간을 측정하고, 최종적으로 로깅을 수행합니다.
• prod 환경에서는 서비스 계층 메서드의 실행 시간만 측정하며, dev, local 환경에서는 애플리케이션의 모든 로직을 감싸고 실행 시간을 측정합니다. (prod 서버에서는 핵심 비즈니스 로직 실행시간만 측정하고, 불필요한 로그 양을 줄이는 방식으로 진행)

ControllerLoggingAspect.java

@Aspect
@Order(2)
@Component
@Profile("!test")
public class ControllerLoggingAspect {
...
...
}

• 해당 클래스는 컨트롤러 계층의 HTTP 요청/응답과 예외를 로깅하여, 외부에서 들어오는 요청이 어떻게 처리되는지 추적할 수 있도록 구현하였습니다.
• @before를 적용해 컨트롤러의 모든 메서드 실행 전 요청 정보를 로깅하고,
• @AfterReturning를 적용해 컨트롤러의 메서드가 정상적으로 실행된 후 응답 데이터를 로깅하고(서비스와 반환 값이 같아 debug레벨로 변경),
• @AfterThrowing을 적용해 컨트롤러에서 예외가 발생했을 때 예외 정보를 로그에 남길 수 있도록 구현했습니다.

ServiceLoggingAspect.java

@Aspect
@Order(3)
@Component
@Profile("!test")
public class ServiceLoggingAspect {
...
...
}

• 해당 클래스는 서비스 계층(또는 애플리케이션 로직)의 메서드 실행 과정을 상세하게 로깅하여, 실행 시간, 인자, 반환값 및 예외 발생 여부를 추적할 수 있도록 구현하였습니다.
• @around는 메서드 실행 전후를 감싸서 로깅하고, System.currentTimeMillis()를 사용해 실행 시간을 측정할 수 있도록 하였고,
• @before를 적용해 서비스 메서드 실행 전에 실행 정보(메서드명, 인자)를 로깅하고,
• @AfterReturning을 적용해 서비스 메서드 실행 후 정상 반환된 값을 로깅하고,
• @AfterThrowing을 적용해 서비스 메서드 실행 중 예외 발생 시 예외 정보를 로깅하고,
• @after를 적용해 서비스 메서드 종료 시점을 로깅할 수 있도록 구현하였습니다.

TxAspect.java

@Aspect
@Order(1)
@Component
@Profile("!test")
public class TxAspect {
...
...
}

• 해당 클래스는 서비스 계층의 트랜잭션 경계를 관리하면서 트랜잭션 관련 상세 정보를 로깅할 수 있도록 구현하였습니다.
• @around를 사용해 다음과 같은 정보를 로깅할 수 있도록 구현하였습니다.
  • 메서드 정보 추출:
    • MethodSignature를 통해 호출되는 메서드의 정보를 추출합니다.
    • 이를 통해 메서드에 붙은 @transactional 애너테이션을 확인합니다.
  • 트랜잭션 옵션 로깅:
    • @transactional 애너테이션이 있다면, readOnly, propagation, isolation 값들을 추출합니다.
    • 이를 통해 어떤 트랜잭션 옵션으로 메서드가 실행되고 있는지 명시적으로 로깅합니다.
  • 실행 시간 측정:
    • 메서드 실행 전후의 시간을 측정하여, 트랜잭션 처리 소요 시간을 로깅합니다.
  • 트랜잭션 처리 결과:
    • 정상 실행 시 커밋, 예외 발생 시 롤백을 로그에 기록합니다.
  • 리소스 릴리즈:
    • finally 블록에서 리소스 해제 시점을 로깅하여, 트랜잭션 관리 흐름을 추적할 수 있습니다.

왜 이렇게 했는가?

• 트랜잭션이 어떻게 처리되는지(시작, 커밋, 롤백, 리소스 해제)를 명확히 기록하면, DB나 기타 리소스 관련 문제 발생 시 원인을 빠르게 파악할 수 있습니다.
• 특히, 서비스 계층의 메서드에 대해 트랜잭션 옵션과 실행 시간 정보를 남기면, 퍼포먼스 최적화 및 오류 디버깅에 큰 도움이 됩니다.

Aspect Order의 순서

• @order(0)인 ExecutionTimeLoggerAspect는 AOP 체인의 가장 처음에 실행되어 전체 실행 시간을 측정합니다.
• @order(1)인 TxAspect는 서비스 로직이 실행되기 전에 트랜잭션 경계를 잡아줍니다.
• @order(2)인 ControllerLoggingAspect는 HTTP 요청과 응답을 로깅하여, 트랜잭션 설정 이후에 컨트롤러 진입 및 종료를 기록합니다.
• @order(3)인 ServiceLoggingAspect는 서비스 메서드의 세부 실행 과정을 로깅합니다.

Trouble Shooting ⚽️

Related ScreenShot 📷

기존 logging 모듈 삭제

---

AS-IS

TO-BE

• Spring에서는 기본적으로 Logback을 이용해서 로깅을 하기 때문에, 다른 로깅 라이브러리인 Log4j2를 그냥 추가하게 되면, 로깅 라이브러리끼리 충돌이 발생합니다.
• 따라서 build.gradle 에서 Logback 설정을 exclude하고 log4j2 설정을 추가했습니다.

AOP 적용 시 로깅

---

• AOP를 적용하고 local에서 홈 API를 조회했을 때 로깅 화면입니다.

Uncompleted Tasks 😅

To Reviewers 📢

log4j2 참고 블로그

AOP 참고 블로그

• local-yml을 노션에 업데이트 해두었으니, 변경해주시면 감사하겠습니다!

[hyerinhwang-sailin]

log4j2 도입 넘 좋네요!!
동기 방식 모니터링 후 비동기 일부 도입하는 방식도 좋습니다!
다만 로그가 한 요청에도 꽤 길어서 prod에서는 좀 더 간소화하는 방향으로 가면 좋을 것 같아요~~