Controller api 가 생각처럼 출력되고 있지 않다

상황

프론트에서 현재 504 타임아웃 서버 에러가 뜬다는 연락을 받았다 (후에 이 상황의 원인은 vercel 의 서버와 백엔드 서버의 지역이 달라서 생기는 타임아웃 문제 였던 것으로 밝혀졌다)

따라서 프론트에서 문제가 생겼다고 말한 api 를 호출해 보는데 로그에서 이상한 것을 발견했다.

18:10:17.702 [http-nio-8080-exec-9][LoginUserId-1] INFO  c.d.c.g.l.a.ControllerLoggingAspect - params : {controller=StudyApi, http_method=GET, method=getDetailInfo, params={}, log_time=Wed Sep 07 18:10:17 KST 2022, request_uri=/api/studies/5}
18:10:19.376 [http-nio-8080-exec-3][LoginUserId-1] INFO  c.d.c.g.l.a.ControllerLoggingAspect - params : {controller=StudyApi, http_method=GET, method=getDetailInfo, params={}, log_time=Wed Sep 07 18:10:19 KST 2022, request_uri=/api/studies/6}
18:10:20.456 [http-nio-8080-exec-6][LoginUserId-1] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null
18:10:23.243 [http-nio-8080-exec-1][LoginUserId-1] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null
18:10:23.371 [http-nio-8080-exec-8][LoginUserId-1] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null
18:10:23.528 [http-nio-8080-exec-2][LoginUserId-1] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null
18:16:07.610 [http-nio-8080-exec-10][LoginUserId-] INFO  c.d.c.g.l.a.ControllerLoggingAspect - params : {controller=StudyApi, http_method=GET, method=getDetailInfo, params={}, log_time=Wed Sep 07 18:16:07 KST 2022, request_uri=/api/studies/1}
18:16:16.604 [http-nio-8080-exec-5][LoginUserId-] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null
18:28:42.056 [http-nio-8080-exec-9][LoginUserId-] INFO  c.d.c.g.l.a.ControllerLoggingAspect - params : {controller=StudyApi, http_method=GET, method=getStudies, params={"size":"1","page":"1","bookId":"1"}, log_time=Wed Sep 07 18:28:42 KST 2022, request_uri=/api/studies}

Error 가 발생하는 상황에는, API 로그가 출력되고 있지 않았다.

왜 그렇지?

사실.. 현재 컨트롤러로의 로그를 출력하는 부분은 급하게 로그를 출력하는 로직을 추가 했던 그 상태 그대로였다..

급하게 필요하다고 해서 해당 코드에 대한 검수를 제대로 하지 못했었다.

AOP 로 작성되어있는데 여기서 뭔가 문제가 생기는 것 같다.

---

(원인)그런데 현재의 AOP 에서는 왜 안되는걸까? 

@Around("loggerPointCut()")
public Object methodLogger(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
   Object result = proceedingJoinPoint.proceed();
   // 로그 출력하기 위해 호출하는 코드들....
}

위의 코드에 문제가 존재했다.

사실 나는 aop 에 대한 제대로된 학습이 되어있지 않았고, 당시 급한 상황에서 코드 리뷰를 제대로 하지 못했다 .. 몹시 부끄럽게 느껴진다. 😥

아무튼

현재 이 메소드가 첫 줄에서 호출되고 있었고 →   여기서 request 에 대한 처리 호출(매핑 핸들러를 호출)이 일어나며 → 그곳에서 예외가 발생하고 → 아래에 존재하는 로깅 코드가 출력되고 있지 않았다.

---

 AOP around 의 proceed() 메소드 동작에 대한 개념을 정리했어야 했다

Advice 메소드의 동작 시점에는

• before(타겟 메소드 실행 전! 에 advice 메소드를 실행)
• after-running(타겟 메소드가 성공적으로 리턴될 경우에 advice 메소드 실행 )
• after-throwing : 타겟 메소드가 실행 중에 예외가 발생할 경우, advice 메소드를 실행
  • 우리에겐 이미 @ControllerAdvice, @RestControllerAdvice 가 있다..
  • exception 이 발생해서 재시도 하는 것이 필요한 상황 정도에 이를 사용 해 볼 수 있을 듯 하다.
• after : 타겟 메소드의 성공 실패 여부와 상관 없이, 타겟 메소드 실행 후 무조건 advice 메소드 동작
• around : 타겟 메소드의 실행 전, 후 advice 메소드가 동작하는 형태

우리의 코드는 @Around 로 작성이 되어있는데, 이에 대해서 알아보자.

Around advice 의 경우, Client 로부터의 호출을 가로 챈다. ( 이어진 호출의 책임도 갖게 되어버림 )

만약

@Around("loggerPointCut()")
public Object methodLogger(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
   return null;
}

이런식으로 코드를 작성할 경우, 타겟 메소드 자체가 실행이 안된다.

우리는 여기서 타겟 메소드는 controller 이기 때문에 이게 실행이 안되면 큰일난다~ 

 

즉, Around Advice 메소드에서는, 타겟 메소드에 대한 호출 책임도 갖고 있다는 것이다.

마치 Servlet filter 에서 doFilter() 내부에서는 chain.doFilter(request, response); 를 호출하여 chain 을 cascade 할 수 있도록 하는 것 과 같다고 생각한다.

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
        throws IOException, ServletException { 
        	...
            
          chain.doFilter(request, response);
    }

또한 서블릿 필터 체인에서 각 필터들은

FilterChain 을 매개변수로 받아와서, 현재 이 필터가 적용되는 필터체인에 대해 알고 -> 다음 필터에 대한 호출을 하는 것 처럼 

Around Advice 메소드 역시 타겟 메소드에 대한 정보를 알고 있어야 한다.

이것이 ProceedingJoinPoint객체 이다. 이는 스프링 컨테이너에서 넘겨준다.

---

결론

결론적으로 원인은 매우 단순하게도 "로그를 출력하는 코드 이전에 컨트롤러를 먼저 호출"하고 있기 때문이었다.

따라서 proceed 를 호출하는 구문만을 가장 뒤로 옮겨주기만 하더라도 원하던 로그를 출력할 수 있다

• 실제 핸들링할 핸들러 에 진입하기 전에 api 로그 출력
• Controller → 서비스….. → DispatcherServlet 까지 처리되는 과정에서 예외 발생시 출력

아래와 같이 예외가 발생하는 상황에서도 API 에 대한 로그가 제대로 출력이 된다

21:38:22.918 [http-nio-8080-exec-1][LoginUserId-1] INFO  c.d.c.g.l.a.ControllerLoggingAspect - params : {controller=StudyApi, http_method=GET, method=getDetailInfo, params={}, log_time=Sun Sep 11 21:38:22 KST 2022, request_uri=/api/studies/29}
21:38:23.033 [http-nio-8080-exec-1][LoginUserId-1] ERROR c.d.c.g.e.h.GlobalExceptionHandler - [ERROR] NullPointerException : Cannot invoke "com.devcourse.checkmoi.domain.study.dto.StudyResponse$StudyDetail.study()" because "studyDetail" is null

---

Around 였을 필요는 없었다

사실 지금처럼 들어오는 API 에 대한 로깅을 하는 용도라면 굳이 @Around 였을 필요는 없는 것 같다. 

@Around 는 "이전", "이후" 모두에 대한 접근을 하는 것이기 때문에 

- 들어오는 API

- API 응답으로 보내 줄 것 

모두를 로깅하는 용도라면 Around 를 사용하는 것을 고려해도 좋을 듯 하다. 

 

하지만 지금 처럼 "들어오는 API 가 무엇인지" 만을 로깅할 목적이었다면 @Before 이 더 적절했을 것 같다 

---

이게 최선일까?

나는 이런 API 에 대한 로그를 출력할 경우 인터셉터를 활용하는 것도 좋을 것 같다는 생각이 들었다.

현재 AOP 에서 request 에 대한 정보를 가져오기 위해서는 추가적으로 직접 RequestContextHolder 에 대한 접근이 이뤄져야 한다.

HttpServletRequest request = ((ServletRequestAttributes) Objects
            .requireNonNull(RequestContextHolder.getRequestAttributes())).getRequest();

하지만 인터셉터를 사용할 경우, preHandle 메소드는 HttpServletRequest 타입 형태 그대로 request 를 매개변수로 받아온다.

@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
   Object handler) throws Exception {

• 타입 캐스팅의 복잡한 과정이 필요없어진다.
• 또한, 위 클래스는 API 에 대한 로깅만을 목적으로 하였기 때문에 인터셉터를 사용했다면 " Controller 에서 핸들링 하기 이전에 호출된다" 는 그 실행 시점의 위치 또한 좀 더 명시적으로 드러낼 수도 있었을 것 같다.

---

참조

https://developer-joe.tistory.com/221