Spring AOP를 이용하여 모든 Request 로그 남기기

0. 들어가며

AOP와 Spring AOP에 대해 알아보자

 

저번 포스트에서 AOP가 무엇인지와 Spring AOP를 사용하는 방법에 대해 간단하게 알아보았다.

 

이전에는 API 요청 정보를 로깅할 때 아래 예시처럼 Controller 메소드마다 모두 직접 적어주었다.

@RestController
@RequestMapping("/api/v1/crews/schedules")
@RequiredArgsConstructor
public class ScheduleController {

    private final ScheduleService scheduleService;

    @PostMapping(value = "")
    public DataResponseDto<Map<String, Long>> createSchedule(
        @RequestBody ScheduleRequestDto scheduleRequestDto
        ) {
        log.info("[POST] 크루 일정 생성 API: /api/v1/crews/schedules");
        return DataResponseDto.of(scheduleService.createSchedule(scheduleRequestDto));
    }

    @GetMapping(value = "")
    public DataResponseDto<Map<String, List<ScheduleResponseDto>>> getAllSchedule() {
        log.info("[GET] 크루 일정 전체 조회 API: /api/v1/crews/schedules");
        return DataResponseDto.of(scheduleService.getAllSchedule());
    }

    // 중략 ...
}

 

그렇다 보니 중복되는 코드가 점점 늘고, 일일이 적어야 하기 때문에 실수(휴먼에러)가 발생하기 쉽고 수정해야 할 경우 모든 코드를 다 고쳐야 하기 때문에 쉽지 않은 작업이다.

 

Spring AOP를 사용해서 API Request에 대한 로그를 출력하는 공통 클래스를 만들어서 비즈니스 로직과 부가적인 로직(로깅 작업)을 분리하고, 반복되는 로깅 작업을 하나의 클래스로 관리해보자!

 

결과물 미리보기

 

LogAspect라는 객체를 구현하여 위와 같은 로그를 출력할 것이다.

나의 요구사항은 다음과 같다.

1. HTTP Method와 URI를 확인할 수 있어야 한다
  - query parameter가 있을 경우 함께 출력한다

2. 어느 메서드를 호출하는지 확인할 수 있어야 한다
  - 병목되는 구간이 있는지 확인하기 위해 실행 시간도 함께 출력한다

---

1. 의존성 추가

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

2. LogAspect 클래스 구현

@Aspect
@Slf4j
@Component
public class LogAspect {

}

@Aspect 어노테이션은 해당 클래스가 횡단관심사 관련 클래스임을 알려주는 어노테이션이다.

Aspect도 Bean 등록을 해주는 것도 잊지 말자.

Pointcut

메서드 호출과 실행 시간 측정 로그는 모든 비즈니스 로직 관련 메서드에 대해서, API Request 로그는 Controller 내 메서드에 대해서 출력해줄 예정이다.

이를 좀 더 AOP스럽게 표현하면 다음과 같다.

Advice	Pointcut
메서드 호출 내역 출력	모든 비즈니스 로직
실행 시간 측정	모든 비즈니스 로직
API Request 내역 출력	Controller 내 메서드

 

@Aspect
@Slf4j
@Component
public class LogAspect {

    @Pointcut("execution(* com.gsm.blabla..*.*(..)) && !execution(* com.gsm.blabla.global..*(..))")
    public void all() {
    }

    @Pointcut("execution(* com.gsm.blabla..*Controller.*(..))")
    public void controller() {
    }
}

 

Pointcut은 정규표현식을 사용하여 표현할 수 있다.

com.gsm.blabla.global은 config나 handler 등을 모아둔 패키지인데, 나는 비즈니스 로직에 관한 메서드만 로그를 출력하고 싶기 때문에 이를 제외해주는 코드를 추가하여 'com.gsm.blabla.global을 제외한 모든 패키지'를 Pointcut으로 하는 all 메서드를 만들어주었다.

API Request를 출력하는 controller 메서드에서는 Controller로 끝나는 클래스의 모든 메서드를 대상으로 하도록 정규표현식을 작성하였다.

 

메서드 호출 내역 및 소요 시간 측정

메서드 호출 전/후, 예외 발생 시점에 Advice를 실행할 수 있도록 @Around 어노테이션을 사용해주었다.

인자로 앞서 작성한 Pointcut을 넣어주어 all()에 대한 상황에 부가기능이 실행되도록 하였다.

@Around("all()")
public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
    long start = System.currentTimeMillis();
    try {
        Object result = joinPoint.proceed();
        return result;
    } finally {
        long end = System.currentTimeMillis();
        long timeinMs = end - start;
        log.info("{} | time = {}ms", joinPoint.getSignature(), timeinMs);
    }
}

joinPoint.proceed()는 비즈니스 메서드의 실행을 제어한다.

다시 말해, joinPoint.proceed() 호출 전은 비즈니스 메서드 호출 전이고, joinPoint.proceed() 호출 후는 비즈니스 메서드 호출 후라고 생각하면 된다.

JointPoint의 Signature에는 클라이언트가 호출한 메서드의 시그니처(리턴 타입, 이름, 매개변수 등) 정보가 담겨 있어 이를 활용하여 호출된 메서드의 정보를 가져올 수 있다.

 

API Request

요청 URI, 헤더 정보, 쿼리 파라미터 등의 정보는 시그니처에 없으므로, RequestContextHolder의 getRequestAttributes 메서드를 사용하여 가져왔다.

 

@Around("controller()")
public Object loggingBefore(ProceedingJoinPoint joinPoint) throws Throwable {
    HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();

    String controllerName = joinPoint.getSignature().getDeclaringType().getName();
    String methodName = joinPoint.getSignature().getName();
    Map<String, Object> params = new HashMap<>();

    try {
        String decodedURI = URLDecoder.decode(request.getRequestURI(), "UTF-8");

        params.put("controller", controllerName);
        params.put("method", methodName);
        params.put("params", getParams(request));
        params.put("log_time", System.currentTimeMillis());
        params.put("request_uri", decodedURI);
        params.put("http_method", request.getMethod());
    } catch (Exception e) {
        log.error("LoggerAspect error", e);
    }

    log.info("[{}] {}", params.get("http_method"), params.get("request_uri"));
    log.info("method: {}.{}", params.get("controller") ,params.get("method"));
    log.info("params: {}", params.get("params"));

    Object result = joinPoint.proceed();

    return result;
}

private static JSONObject getParams(HttpServletRequest request) {
    JSONObject jsonObject = new JSONObject();
    Enumeration<String> params = request.getParameterNames();
    while (params.hasMoreElements()) {
        String param = params.nextElement();
        String replaceParam = param.replaceAll("\\.", "-");
        jsonObject.put(replaceParam, request.getParameter(param));
    }
    return jsonObject;
}

 

로그를 출력할 때 바로 controllerName, methodName 등을 넘겨도 되지만, 예외가 발생할 경우를 대비하여 try-catch문으로 출력할 정보를 params라는 맵에 담고 params 맵에서 원소를 꺼내는 방법으로 원하는 정보들을 가져와 로그를 출력하였다.

 

URI에 한글이 있을 때 글자가 깨져서 나와서 디코딩 작업을 하는 코드도 한 줄 추가해주었다.

 

getParams 메서드는 쿼리 파라미터를 JSON 형태로 변환해주는 메서드이다.

 

전체 코드

@Aspect
@Slf4j
@Component
public class LogAspect {

    @Pointcut("execution(* com.gsm.blabla..*.*(..)) && !execution(* com.gsm.blabla.global..*(..))")
    public void all() {
    }

    @Pointcut("execution(* com.gsm.blabla..*Controller.*(..))")
    public void controller() {
    }

    @Around("all()")
    public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
        long start = System.currentTimeMillis();
        try {
            Object result = joinPoint.proceed();
            return result;
        } finally {
            long end = System.currentTimeMillis();
            long timeinMs = end - start;
            log.info("{} | time = {}ms", joinPoint.getSignature(), timeinMs);
        }
    }

    @Around("controller()")
    public Object loggingBefore(ProceedingJoinPoint joinPoint) throws Throwable {
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();

        String controllerName = joinPoint.getSignature().getDeclaringType().getName();
        String methodName = joinPoint.getSignature().getName();
        Map<String, Object> params = new HashMap<>();

        try {
            String decodedURI = URLDecoder.decode(request.getRequestURI(), "UTF-8");

            params.put("controller", controllerName);
            params.put("method", methodName);
            params.put("params", getParams(request));
            params.put("log_time", System.currentTimeMillis());
            params.put("request_uri", decodedURI);
            params.put("http_method", request.getMethod());
        } catch (Exception e) {
            log.error("LoggerAspect error", e);
        }

        log.info("[{}] {}", params.get("http_method"), params.get("request_uri"));
        log.info("method: {}.{}", params.get("controller") ,params.get("method"));
        log.info("params: {}", params.get("params"));

        Object result = joinPoint.proceed();

        return result;
    }

    private static JSONObject getParams(HttpServletRequest request) {
        JSONObject jsonObject = new JSONObject();
        Enumeration<String> params = request.getParameterNames();
        while (params.hasMoreElements()) {
            String param = params.nextElement();
            String replaceParam = param.replaceAll("\\.", "-");
            jsonObject.put(replaceParam, request.getParameter(param));
        }
        return jsonObject;
    }
}

 

Reference

[Project] Spring AOP로 로그 / 알림 Aspect 구현하기 !

[spring] AOP를 이용하여 controller의 input data 자동 로그 기록하기

AOP around의 proceed() 메소드 동작에 대한 개념 정리