이슈 배경

클라이언트가 어떤 정보로 어떤 API를 호출했는지 확인하고자 했습니다.

또, Request가 처리되는데 얼마나 걸렸는지 알 수 있다면 "문제가 발생했을 때 어느 지점에서 시간이 오래 소요됐는지 빠르게 파악할 수 있지 않을까?" 하는 생각이 들었습니다.

❓ AOP (Aspect Oriented Programming)

코드를 두 개의 관점으로 나누고, 공통된 로직 또는 기능을 하나의 단위로 묶어 모듈화하는 것으로 관점 지향 프로그래밍이라고 합니다.

• 핵심: 비즈니스 로직
• 부가: DB 연결, 로깅, 파일 입출력, 트랜잭션, 보안, 캐싱 등

  부가적인 코드를 핵심 비즈니스 로직에서 분리해 재사용합니다.

Spring AOP의 특징

1. 프록시 패턴 기반의 AOP 구현체
   • 런타임에 프록시 인스턴스가 동적으로 변경되는 다이나믹 프록시 기법으로 구현
   • 접근 제어 및 부가 기능을 추가하기 위해 사용
2. Spring Bean에만 적용 가능 @Aspect, @Component
3. Spring IoC와 연동해 문제 해결
   • 엔터프라이즈 애플리케이션에서 발생하는 흔한 문제(코드 중복, 객체 관계 복잡도 증가 등)를 해결하는 것이 목적

주요 개념

• Aspect : 흩어진 관심사를 모듈화한 것
• Target : Aspect 적용 위치 (클래스, 메서드 등)
• Advice : 실질적인 부가 기능 구현체 (어떤 일을 할 것인지)
• JoinPoint : Advice 적용 위치 (메서드 진입 지점, 생성자 호출 지점 등)
• PointCut : JoinPoint의 상세 스펙 (구체적인 Advice의 실행 시점)
  • 예) A 메서드 진입 시점에 호출하기

Logging 구현하기

LogAspect 클래스를 구현해 위와 같이 로그를 출력해보겠습니다.

---

개발 환경

• Spring Boot 3
• Java 17
• Spring Security

해당 포스팅의 실제 코드는 EunsilSon - BookMarky에서 확인할 수 있습니다.

---

🟢 AOP 의존성 추가

	implementation 'org.springframework.boot:spring-boot-starter-aop'

---

Request 정보

🟢 Pointcut ; 진입 시점

@Pointcut("execution(* com.eunsil.bookmarky..*Controller.*(..))")
    public void controller() {
}

• 요청을 받는 Controller에 진입하는 시점에 로그를 출력하기 위해 Pointcut을 생성합니다.
• 위 패턴은 com.eunsil.bookmarky 패키지 내의 모든 Controller 클래스의 모든 메서드, 모든 매개변수를 의미하는 패턴입니다.

  execution 표현식
  execution(<access-modifier> <return-type> <class-name>.<method-name>(<parameters>))

---

🟢 @Before ; 컨트롤러 실행 전

• 컨트롤러 실행과 상관 없이, 어떤 클라이언트에 의해 어떤 API가 호출이 됐는지 파악하기 위해 @Before 어노테이션을 사용했습니다.
• 사용자 이름, HTTP 메서드, URI, 실행될 컨트롤러 이름, 실행될 메서드 이름를 출력합니다.

@Before("controller()")
    public void logBeforeExecution(JoinPoint joinPoint) throws Throwable {
    	// Request 정보
        HttpServletRequest request = ((ServletRequestAttributes) Objects.requireNonNull(RequestContextHolder.getRequestAttributes())).getRequest();
		String username = request.getUserPrincipal() != null ? request.getUserPrincipal().getName() : "None";
        
        
        // 호출된 컨트롤러와 메서드 정보
        String controllerName = joinPoint.getSignature().getDeclaringTypeName();
        String methodName = joinPoint.getSignature().getName();
        Map<String, Object> params = new HashMap<>();


		// URI 인코딩 및 출력에 필요한 변수들
        try {
            String decodedRequestURI = URLDecoder.decode(request.getRequestURI(), StandardCharsets.UTF_8);
            params.put("controller", controllerName);
            params.put("method", methodName);
            params.put("http_method", request.getMethod());
            params.put("request_uri", decodedRequestURI);
            params.put("user", username);
        } catch (Exception e) {
            log.error("LogAspect Error", e);
        }


		// 로그 출력
        log.info("Request - HTTP: {} | URI: {} | User: {} | Method: {}.{}",
                params.get("http_method"),
                params.get("request_uri"),
                params.get("user"),
                params.get("controller"),
                params.get("method"));
    }

• @Before() : 메서드 실행 전에 실행되는 Advice(부가기능) 임을 나타냅니다.
  • 정의해둔 Pointcut으로 대상 메서드 지정
• JoinPoint : Advice가 적용되는 메서드의 호출 지점에 대한 정보를 제공합니다.
  • 호출된 Controller와 Method의 이름 추출
• RequestContextHolder : HTTP Method, 요청 URI, 헤더 정보, 쿼리 파라미터, 사용자 이름 등의 정보를 제공합니다.

로그에 출력할 변수들을 Map에 넣고 다시 Map에서 꺼낸 이유는, 여러 개의 로깅 데이터들을 쉽게 추가하고 삭제하기 위함입니다.

또한, log 출력 코드에서 코드 가독성을 높일 수 있었습니다.

---

메서드 수행 시간

🟢 @Around ; 메서드 실행 전후

시작 시간과 종료 시간을 측정하기 위해 @Around 어노테이션을 사용했습니다.

@Around("controller()")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    long start = System.currentTimeMillis();

    try {
        return joinPoint.proceed();
    } finally {
        long end = System.currentTimeMillis();
        long timeMs = end - start;
        log.info("Execution Time: {} ms", timeMs);
    }
}

proceed() 호출 전의 시작 시간을 기록하고, finally 블록에서 종료 시간을 측정해 두 시간의 차이를 계산합니다.

❓ JoinPoint와 PreceedingJoinPoint의 차이

메서드 실행 전후를 제어하는 @Around 메서드에는 PreceedingJoinPoint를 매개변수로 받고,
메서드 실행 전을 제어하는 @Before 메서드에서는 PreceedingJoinPoint을 사용하지 못하고 JoinPoint를 매개변수로 받아야 했습니다.

둘 다 AOP Advice에서 메서드 실행과 관련된 정보를 제공하는 인터페이스이지만, 제공 기능과 목적에 차이가 있었습니다.

PreceedingJoinPoint는 JoinPoint의 하위 인터페이스로, @Around Advice에서 사용됩니다.

JoinPoint에서 제공하는 메서드 외에, 대상 메서드를 실제 실행할 수 있는 proceed() 메서드를 제공합니다. 메서드 실행 흐름을 제어할 수 있었습니다. (트랜잭션, 성능 측정, Return 값 변경, 예외 처리)

---

전체 코드

@Slf4j
@Aspect
@Component
public class LogAspect {
    @Pointcut("execution(* com.eunsil.bookmarky..*Controller.*(..))")
    public void controller() {
    }

    @Around("controller()")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        long start = System.currentTimeMillis();

        try {
            return joinPoint.proceed();
        } finally {
            long end = System.currentTimeMillis();
            long timeMs = end - start;
            log.info("Execution Time: {} ms", timeMs);
        }
    }

    @Before("controller()")
    public void logBeforeExecution(JoinPoint joinPoint) throws Throwable {
        HttpServletRequest request = ((ServletRequestAttributes) Objects.requireNonNull(RequestContextHolder.getRequestAttributes())).getRequest();

        String username = request.getUserPrincipal() != null ? request.getUserPrincipal().getName() : "None";
        String controllerName = joinPoint.getSignature().getDeclaringTypeName();
        String methodName = joinPoint.getSignature().getName();
        Map<String, Object> params = new HashMap<>();

        try {
            String decodedRequestURI = URLDecoder.decode(request.getRequestURI(), StandardCharsets.UTF_8);
            params.put("controller", controllerName);
            params.put("method", methodName);
            params.put("http_method", request.getMethod());
            params.put("request_uri", decodedRequestURI);
            params.put("user", username);
        } catch (Exception e) {
            log.error("LogAspect Error", e);
        }

        log.info("Request - HTTP: {} | URI: {} | User: {} | Method: {}.{}",
                params.get("http_method"),
                params.get("request_uri"),
                params.get("user"),
                params.get("controller"),
                params.get("method"));
    }

}

reference

https://velog.io/@wnguswn7/Project-Spring-AOP%EB%A1%9C-%EB%A1%9C%EA%B7%B8-%EC%95%8C%EB%A6%BC-%EA%B8%B0%EB%8A%A5-%EA%B5%AC%ED%98%84%ED%95%98%EA%B8%B0

https://leeeeeyeon-dev.tistory.com/51