[Spring Boot] 로그, 노가다 그만! AOP로 요청/응답/시간 자동 기록하기

 

log.info를 일일이 찍는 기초 단계를 넘어서, "숨만 쉬어도(API 호출만 해도) 로그가 자동으로 남는" AOP(Aspect Oriented Programming, 관점 지향 프로그래밍) 시스템을 구축해 보겠습니다.

특히 우리가 만든 JWT 인증 시스템과 연동하여, "누가(User ID) 요청했는지"까지 자동으로 남기는 코드로 작성해 드립니다.

1. 왜 AOP 인가요?

컨트롤러가 100개라고 가정해 봅시다. 모든 메소드에 아래 코드를 넣으실 건가요?

// 😱 끔찍한 노가다의 현장
public String hello() {
    log.info("hello 메소드 시작"); // 반복
    long start = System.currentTimeMillis(); // 반복

    // ... 비즈니스 로직 ...

    long end = System.currentTimeMillis(); // 반복
    log.info("hello 메소드 종료. 걸린 시간: " + (end - start) + "ms"); // 반복
}

AOP를 사용하면 이 반복되는 코드(횡단 관심사)를 싹 걷어내어 "CCTV"처럼 별도 클래스로 분리할 수 있습니다. 비즈니스 로직은 건드리지 않고도요!

---

Step 1. 의존성 추가 (build.gradle)

AOP 라이브러리를 추가합니다.

dependencies {
    // AOP (Aspect Oriented Programming)
    implementation 'org.springframework.boot:spring-boot-starter-aop'
}

---

Step 2. 요청자 추적하기 (MDC 설정)

로그에서 가장 중요한 건 "누가 범인인가?" 입니다.
우리의 JwtAuthenticationFilter는 토큰을 검사하는 곳이죠? 여기서 유저 아이디를 꺼내 MDC(Mapped Diagnostic Context)라는 곳에 넣어두면, 로그를 찍을 때마다 자동으로 꼬리표처럼 따라다니게 할 수 있습니다.

• 위치: src/main/java/com/example/board/jwt/JwtAuthenticationFilter.java

// ... 기존 import ...
import org.slf4j.MDC; // ★ 추가

@RequiredArgsConstructor
public class JwtAuthenticationFilter extends GenericFilterBean {

    private final JwtTokenProvider jwtTokenProvider;

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        String token = resolveToken((HttpServletRequest) request);

        // 1. 토큰 검증 및 유저 정보 추출
        if (token != null && jwtTokenProvider.validateToken(token)) {
            Authentication authentication = jwtTokenProvider.getAuthentication(token);
            SecurityContextHolder.getContext().setAuthentication(authentication);

            // ★ [핵심] 로그 추적을 위해 MDC에 userId 저장
            MDC.put("userId", authentication.getName());
        } else {
            // 로그인 안 한 경우
            MDC.put("userId", "anonymous");
        }

        try {
            chain.doFilter(request, response);
        } finally {
            // ★ [매우 중요] 요청이 끝나면 MDC를 비워줘야 함 (스레드 풀 재사용 문제 방지)
            MDC.clear();
        }
    }
    // ...
}

---

Step 3. AOP 로깅 Aspect 구현 (LogAspect)

이제 "자동 로그 기록기(CCTV)"를 만듭니다.
@Aspect 어노테이션을 사용하여 컨트롤러에 들어오는 모든 요청을 가로채서 기록합니다.

• 위치: src/main/java/com/example/board/config/LogAspect.java

package com.example.board.config;

import jakarta.servlet.http.HttpServletRequest;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

@Slf4j
@Aspect
@Component
public class LogAspect {

    // 1. 적용 범위 설정: controller 패키지 하위의 모든 메서드
    @Pointcut("execution(* com.example.board.controller..*.*(..))")
    public void controller() {}

    // 2. 메서드 실행 전후(Around)에 로직 끼워넣기
    @Around("controller()")
    public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
        // (1) 요청 정보 가져오기
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest();

        String method = request.getMethod();     // GET, POST
        String uri = request.getRequestURI();    // /members/login
        String methodName = joinPoint.getSignature().getName(); // 실행되는 메서드 이름

        // (2) 시작 로그
        log.info("======== [Request] {} {} | Method: {} ========", method, uri, methodName);

        long startTime = System.currentTimeMillis();

        try {
            // (3) ★ 실제 타겟(Controller) 메서드 실행
            Object result = joinPoint.proceed();

            // (4) 종료 로그 (정상 수행 시)
            long endTime = System.currentTimeMillis();
            long executionTime = endTime - startTime;

            log.info("======== [Response] {} {} | Time: {}ms ========", method, uri, executionTime);

            return result;
        } catch (Throwable e) {
            // (5) 예외 발생 시 로그
            log.error("======== [Exception] {} {} | Msg: {} ========", method, uri, e.getMessage());
            throw e; // 에러를 삼키지 말고 다시 던져야 클라이언트에게 에러 응답이 감
        }
    }
}

---

Step 4. 로그 포맷 설정 (application.yml)

이제 아까 MDC에 넣어둔 userId가 로그 맨 앞에 출력되도록 포맷을 바꿔봅시다.

• 위치: src/main/resources/application.yml

logging:
  pattern:
    # 날짜 [스레드] [유저ID] 레벨 클래스 - 메시지
    console: "%d{HH:mm:ss.SSS} [%thread] [%X{userId}] %-5level %logger{36} - %msg%n"
  level:
    root: INFO
    com.example.board: DEBUG

• [%X{userId}]: 여기가 마법의 주문입니다. MDC에서 userId 값을 꺼내서 출력하라는 뜻입니다.

---

Step 5. 실행 및 결과 확인

서버를 실행하고 API를 호출해 보세요.

1. 로그인 없이 /members/test 호출 시:

14:30:01.123 [http-nio-8080-exec-1] [anonymous] INFO  c.e.b.config.LogAspect - ======== [Request] GET /members/test | Method: test ========
14:30:01.130 [http-nio-8080-exec-1] [anonymous] ERROR c.e.b.config.LogAspect - ======== [Exception] GET /members/test | Msg: Access Denied ========

👉 [anonymous]라고 찍히며 에러가 기록됩니다.

2. 로그인(user1) 후 /members/test 호출 시:

14:35:05.555 [http-nio-8080-exec-5] [user1] INFO  c.e.b.config.LogAspect - ======== [Request] GET /members/test | Method: test ========
14:35:05.570 [http-nio-8080-exec-5] [user1] INFO  c.e.b.config.LogAspect - ======== [Response] GET /members/test | Time: 15ms ========

👉 [user1] 이라는 아이디가 선명하게 찍히고, 실행 시간(15ms)까지 자동으로 계산되었습니다!

---

💡 전체 동작 원리 (Sequence)

AOP가 필터와 컨트롤러 사이에서 어떻게 동작하는지 그림으로 이해해 보세요.

---

🎉 마무리

이제 여러분은 비즈니스 로직(Controller)에 로깅 코드를 한 줄도 쓰지 않아도 됩니다.
AOP가 알아서 감시하고, MDC가 알아서 이름을표를 붙여주니까요.
이게 바로 "관점(Aspect)을 분리하여 핵심 로직에 집중한다"는 AOP의 매력입니다! 😎