😠 발생한 문제

프론트앤드 개발자분들과 함께 애플리케이션을 개발하면서 가끔 백엔드 서버의 문제로 어떤 예외가 발생했으니 확인을 부탁드린다는 요청을 받을때가 있습니다.

특히 NPE(NullPointerException)와 같이 빈번히 발생하는 예외라면 어떤 파라미터가 비어서 들어왔거나 Service에서 빈 매개변수의 값을 참조하지는 않았거나 여러 예외의 원인이 있을 수 있습니다.

이런 경우 어떻게 문제를 파악하고 해결해가야할지 시간도 오래 걸리고 막막할 수 있다는 생각이 들어서, 모든 요청에 대해 파라미터 값을 로깅하기로 결정하였습니다.

👾 Controller 안에서 모든 파라미터를 찍어볼 것인가?

먼저 생각한 방법은 Controller 메서드안에서 request 객체를 이용해 모든 파라미터 정보를 출력하고, 매개변수의 값들을 출력하는 방법입니다.

어떤 메서드의 요청인지, 요청 시작 시간은 언제인지 들어온 파라미터의 값들을 전부 출력하고 있습니다.
이런 중복되는 로직을 모든 컨트롤러 메서드마다 수행해야 하는 것입니다.

그렇다면 이 로직을 컨트롤러에서 빼내서 공통 메서드로 분리하면 문제가 해결될까요?

이 printLog라는 메서드를 컨트롤러마다 중복으로 호출해줘야 한다는 사실은 변함이 없습니다.
컨트롤러마다 들어오는 요청에 대해서 파라미터의 이름과 타입 그리고 바인딩 되어 있는 값과 요청의 시작시간과 종료시간을 알고 싶은 것은 공통 관심사에 해당됩니다.

이렇게 공통적으로 같은 관심사를 가지고 부가적인 기능을 수행할 로직을 분리할 수 있도록 도와주는 것이 AOP 입니다.
AOP에 대해 처음 들어보셨거나 생소하신분이 이 글을 참고해주시면 되겠습니다.

🤟 AOP를 이용한 로깅 클래스 개발

먼저 AOP 기능을 사용하기 위해 의존성을 추가 해주겠습니다.

LogAspect 클래스를 작성해서 모든 컨트롤러의 요청에 대해 요청 시작시간과 종료시간, 파라미터의 타입과 값을 볼 수 있도록 해보겠습니다.

@Aspect
@Slf4j
@Component
public class LogAspect {

    @Pointcut("execution(* com.adoptpet.server.adopt.controller..*.*(..))")
    public void adoptBeforeExecute() {}

    @Pointcut("execution(* com.adoptpet.server.community.controller..*.*(..))")
    public void communityBeforeExecute() {}

    @Pointcut("execution(* com.adoptpet.server.user.controller..*.*(..))")
    public void userBeforeExecute() {}

    @Before("adoptBeforeExecute() || userBeforeExecute() || communityBeforeExecute()")
    public void requestLogging(JoinPoint joinPoint) {

        // 실행되는 메서드 이름을 가져오고 출력
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        Method method = methodSignature.getMethod();
        log.info(method.getName() + "() 메서드 요청 시작");

        log.info("요청 시작 시간 = {}", LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss")));

        // 메서드에 들어가는 매개변수 배열을 읽어온다.
        Object[] paramArgs = joinPoint.getArgs();

        // 매개변수 배열의 종류와 값을 출력한다.
        for (Object object : paramArgs) {
            if (Objects.nonNull(object)) {
                log.info("parameter type => {}", object.getClass().getSimpleName());
                log.info("parameter value => {}", object);
            }
        }

    }

    @AfterReturning("adoptBeforeExecute() || userBeforeExecute() || communityBeforeExecute()")
    public void afterRequesting(JoinPoint joinPoint) {
        // 실행되는 메서드 이름을 가져온다
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        Method method = methodSignature.getMethod();
        
        log.info("요청 종료 시간 = {}", LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss")));
        log.info("요청 종료 , 종료된 메서드 => {}", method.getName());
    }

    @AfterThrowing(pointcut = "adoptBeforeExecute() || userBeforeExecute() || communityBeforeExecute()", throwing = "exception")
    public void exceptionLogging(JoinPoint joinPoint, Exception exception) {
        // 실행되는 메서드 이름을 가져오고 출력
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        Method method = methodSignature.getMethod();
        log.error(method.getName() + "() 메서드 처리 중 예외 발생!!");

        log.error("예외 발생 시간 = {}", LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss")));
    }

}

한 줄씩 뜯어서 살펴보겠습니다.

개발한 클래스를 Spring Bean으로 등록하기 위해서 @Component를 붙여줘야 합니다. Component Scanner는 @Component가 붙은 클래스를 Spring Bean으로 등록합니다.

@Aspect는 AOP를 사용하는 클래스에 붙여줘야 하는 애너테이션입니다.

@Pointcut은 AOP의 기능을 어디에 적용시킬지 지점을 설정할 수 있는 애너테이션입니다. 애너테이션에 설정할 수도 있고, 특정 패키지 하위의 메서드에 적용시킬 수 도 있습니다. 다양한 수식을 통해 타깃을 설정할 수 있습니다.

저는 Adopt(분양), Community(게시판), User(회원) 총 3개의 도메인에 대한 요청을 담당하는 컨트롤러들에 대해서 AOP 기능을 적용하겠습니다.

위에서 작성한 세개의 메서드 이름이 논리합 연산자로 이어져 있습니다.
@Before는 위에서 지정한 분양, 게시판, 회원 3개의 도메인에 대한 컨트롤러들의 요청이 시작되기 전에 실행하라는 뜻입니다. 실행되는 메서드의 이름을 가져오고, 요청이 들어온 컨트롤러 메서드의 이름과 요청 시작시간, 파라미터의 종류와 값을 출력합니다.

이 부분에서 약간 의문이 들 수 있는 부분이 매개변수 배열을 읽어올때, 매개변수가 하나도 없다면 null 이기 때문에 for 문을 돌기전에 먼저 null check를 하면 되는거 아닐까라고 생각했습니다.

결론부터 말씀드리면 그렇게 코드를 작성하면 NPE(NullPointerException)이 발생하게 됩니다.
이 문제가 발생하는 이유는 JoinPoint 인터페이스의 구현체인 JoinPointImpl을 보면 알 수 있습니다.

메서드에 들어가는 매개변수 배열을 가져오는 getArgs 메서드의 구현 부분입니다.

args가 null일 경우 길이가 0인 Object 배열을 넣어줍니다.
이렇게 작동하기 때문에, 얻어온 매개변수 배열은 객체가 null이 아니지만 내부의 값이 없기 때문에 for 문을 돌면서 참조할 경우에 NPE가 발생하는 문제가 생기게됩니다.

이 부분은 메서드가 성공적으로 종료되었을때 실행되는 메서드입니다.
메서드가 시작하기 전에 @Before 애너테이션이 붙은 메서드에서 요청의 시작 시간과 실행되는 메서드의 이름, 파라미터들의 타입과 값을 로그로 찍어주었으니 여기서는 요청 종료시간과 종료된 메서드의 이름만 보여주면 됩니다.

@AfterThrowing이 붙은 메서드는 메서드가 성공적으로 종료되지 못하고, 예외가 발생했을 경우 동작하는 메서드입니다.
예외가 발생한 메서드의 이름을 error 로그로 알려주고, 예외 발생시간을 로깅하도록 작성해주었습니다.

이제 정상적으로 로깅 클래스가 동작하는지 테스트를 해보겠습니다.

요청이 성공적으로 종료된경우

중간에 다른 로그들이 섞이긴했지만, 요청의 시작과 종료 시간이 잘찍혀있는 것을 볼 수 있습니다.
지금 파라미터 없이 요청을 해서 아무것도 찍히지 않았기때문에 파라미터를 넣어서 요청해보겠습니다.

바인딩되어 있는 파라미터의 값들도 잘 출력된 것을 볼 수 있습니다.

요청이 실행 중 예외가 발생한경우

회원 정보 수정 API에서 중복된 닉네임으로 요청한 경우, 예외가 발생합니다.
이 경우, 어떤 메서드에서 예외가 발생했는지와 예외 발생 시간을 알 수 있는 로그가 출력되는 것을 볼 수 있습니다.

😈 문제를 해결하며 느낀점

AOP에 대해서 처음 배웠을때는 이게 왜 필요한지 이것이 무엇이길래 Spring의 3대 핵심 개념안에 들어가는건지 이해하기가 어려웠습니다.

하지만 Spring에서 다양하게 활용되고 있는 부분이 AOP라는 것을 Spring을 공부할수록 자주 등장하게 되었고 이번 프로젝트에서 로그를 찍는 부분을 공통 관심사로 분리해 간단하게 처리할 수 있는 것을 보고 아주 강력한 기능이라는 것을 몸소 체험했습니다.

앞으로는 어떻게 하면 Spring에서 제공하는 강력한 기능들을 만드는 애플리케이션에서 함께 융합시킬 수 있을지 생각해보려고 노력하겠습니다.

오늘도 읽어 주셔서 감사합니다.

🙇