[Toy Project] Spring AOP와 로깅을 위한 Aspect 구현하기

AOP

Aspect-Oriented Programming (관점 지향 프로그래밍)

• 개발에서 반복되는 관심사 (로깅, 보안, 트랜젝션)를 모듈화하는 프로그래밍 접근 방법
• 관심사를 분리하여 코드의 재사용성과 유지보수성을 높일 수 있음. 횡단 관심사를 적용
• Spring AOP는 런타임에 프록시를 사용하여 이러한 관심사를 적용

Aspect, Advice, Pointcut

Aspect	관심사의 모듈화된 버전 ex) 로깅, 트랜젝션 관리
Advice	Aspect가 언제 실행될지를 정의 ex) Before, After, Around
Pointcut	Advice가 적용될 위치. 즉 어떤 메서드 실행 전후에 적용될지 정의

로깅을 위한 Aspect 구현

• 애플리케이션의 컨틀롤러와 (API 실행 시간) 레포지토리 레이어 (DB 접속 시간)에 대한 로깅을 자동화하였다

  • @Aspect: 해당 클래스가 Aspect임을 선언하는 어노테이션
  • 로거 설정: SLF4J 로거 인스턴스 생성. API 호출과 DB 접근에 대한 정보 로깅에 사용
  • Advice 정의
    • @Around: 컨트롤러 메서드의 실행을 감싸 API의 시작과 종료 시점에 요청 과 응답을 로깅, 실행 시간도 계산하여 로깅
    • @Before, @After: 데이터데이스의 접근의 시작과 종료 시점에 로깅 -> DB 접속 시간 측정
  • joinpoint : 프로그램 실행 중에 특정 지점 (ex 메서드 호출)을 나타냄. 즉 advice가 적용될 수 있는 위치를 의미
    • 주요 기능: 메서드 실행 정보 제공(메서드 이름, 메서드를 소유하고 있는 객체, 메서드 인자), 프로그램 실행 흐름에 개입(로깅, 예외처리)

@Aspect
@Component
public class LoggingAspect {

    private static final Logger logger = LoggerFactory.getLogger(LoggingAspect.class);
    private static final ThreadLocal<Long> startTime = new ThreadLocal<>();
    private static final ThreadLocal<Long> dbStartTime = new ThreadLocal<>();

    @Autowired
    private ObjectMapper objectMapper = new ObjectMapper()
            .enable(SerializationFeature.INDENT_OUTPUT);

    @Value("${study.systemId}")
    protected String systemId;

    private String serializeObjectToJson(Object object) {
        try {
            return objectMapper.writeValueAsString(object);
        } catch (JsonProcessingException e) {
            logger.error("JSON serialization error", e);
            return "Error serializing object to JSON";
        }
    }


    @Around("execution(* mogakco.StudyManagement.controller..*(..))")
    public Object logControllerAccess(ProceedingJoinPoint joinPoint) throws Throwable {
        long start = System.currentTimeMillis();
        startTime.set(start);

        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        logger.info("Started API: {} {} in system {}",
                request.getMethod(),
                request.getRequestURL().toString(),
                systemId);

        Object result = joinPoint.proceed();
        String responseBodyJson = serializeObjectToJson(result);

        long executionTime = System.currentTimeMillis() - startTime.get();
        startTime.remove();

        logger.info("Completed API: {} with responseBody: {} in {} ms",
                request.getRequestURL().toString(),
                responseBodyJson,
                executionTime);

        return result;
    }

    @Before("execution(* mogakco.StudyManagement.repository..*(..))")
    public void logDbAccessStart(JoinPoint joinPoint) {
        long start = System.currentTimeMillis();
        dbStartTime.set(start);
        logger.info("DB Access Start: {}", joinPoint.getSignature().getName());
    }

    @After("execution(* mogakco.StudyManagement.repository..*(..))")
    public void logDbAccessEnd(JoinPoint joinPoint) {
        long end = System.currentTimeMillis();
        long duration = end - dbStartTime.get();
        dbStartTime.remove();
        logger.info("DB Access End: {} took {} ms", joinPoint.getSignature().getName(), duration);
    }

}

로깅 예시

2024-02-11 20:43:48.736 [main] INFO  LoggingAspect - Started API: GET http://localhost/api/v1/posts/9103 in system STUDY_0001
2024-02-11 20:43:48.736 [main] INFO  LoggingAspect - DB Access Start: findById
2024-02-11 20:43:48.742 [main] INFO  LoggingAspect - DB Access End: findById took 6 ms
2024-02-11 20:43:48.743 [main] INFO  LoggingAspect - DB Access Start: countByPostPostId
2024-02-11 20:43:48.748 [main] INFO  LoggingAspect - DB Access End: countByPostPostId took 5 ms
2024-02-11 20:43:48.748 [main] INFO  LoggingAspect - DB Access Start: findByPostPostIdAndParentCommentIsNull
2024-02-11 20:43:48.754 [main] INFO  LoggingAspect - DB Access End: findByPostPostIdAndParentCommentIsNull took 6 ms
2024-02-11 20:43:48.755 [main] INFO  LoggingAspect - DB Access Start: countRepliesByPostId
2024-02-11 20:43:48.765 [main] INFO  LoggingAspect - DB Access End: countRepliesByPostId took 10 ms
2024-02-11 20:43:48.772 [main] INFO  LoggingAspect - Completed API: http://localhost/api/v1/posts/9103 with responseBody: {"systemId":"STUDY_0001","retCode":200,"retMsg":"성공","postDetail":{"memberName":"PostUser","likes":1,"title":"post2","content":"content2","createdAt":"2024021124114348718958","updatedAt":"2024021124114348718958","comments":[{"commnetId":2266,"memeberName":"PostUser","content":"comment1","createdAt":"2024021124114348725038","updatedAt":"2024021124114348725038","replyCnt":1}]}} in 36 ms

후기

• 기존에도 토이 프로젝트에서 로깅 서비스를 다음과 같이 구현해서 사용하고 있었다 -> 이전 방식
• 하지만 "로깅, 트랜젝션과 같은 횡단적 관심사는 AOP로 처리한다"라는 내용을 CS 공부할 때 배우면서, 내가 과연 배운 걸 써먹고 있는가? 에 대한 고민이 있었다 그래서 Backend 개발과 내 담당의 UI 개발까지 끝낸 뒤 꼭 해보고 싶었던 AOP를 적용해보았다
• 확실히 느낀 좋은 점은 API controller 단이나 서비스 로직에서 로깅과 관련된 로직을 전혀 추가하지 않아도, LoggingAspect 에서 API 실행 시마다 잡아서 처리해주니 비지니스 로직에만 집중할 수 있어 훨씬 편리했다!
• 하나 개선점은 DB 접근할 때마다 로깅을 남기는 것도 좋지만, 하나의 API 실행 시 총 DB 접근 시간도 구할 수 있었으면 좋겠다 또 발전시켜봐야겠다 👊👊