과제를 진행하면서 구현했던 API 로깅에 대해서 어려웠던 부분과 알게 된 부분을 적어보려고 한다.
Interceptor VS AOP
과제에 제시된 구현 방법은 인터셉터와 AOP 두 가지였는데 나는 AOP를 선택하였다. Admin 사용자만 접근할 수 있는 API의 실행 전후에 로깅을 한다는 세부 구현의 내용이 좀 더 주제에 맞는 것 같다고 생각했다. 또한, 인터셉터를 사용할 경우엔 SecurityContextHolder 또는 HttpServletRequest에서 사용자의 인증 정보를 가져올 수 있는데 나도 모르게 스프링 시큐리티를 사용하고 있을 것 같다는 생각이 들어서 인터셉터를 배제한 이유도 있다.
AOP로 구현하기
횡단 관심사라는 것을 나타내기 위해 @Aspect를 사용하고, 메소드 호출 전 / 후에 로깅을 해야하기 때문에 @Around를 사용하였다. 그리고 Admin 사용자만 접근할 수 있는 API라는 조건이 주어졌기 때문에 @Pointcut을 사용해서 Aspect가 언제 적용될 지 정의하였다.
@Slf4j @Aspect @Component @RequiredArgsConstructor public class AdminApiLogging { private final ObjectMapper objectMapper; @Around("adminMethodA() || adminMethodB()") public Object adminApiLogging(ProceedingJoinPoint joinPoint) throws Throwable { HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest(); HttpServletResponse response = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getResponse(); ContentCachingRequestWrapper wrappedRequest = new ContentCachingRequestWrapper(request); ContentCachingResponseWrapper wrappedResponse = new ContentCachingResponseWrapper(response); String requestBody = getRequestBody(wrappedRequest); Long userId = (Long) request.getAttribute("userId"); log.info("API Request Log - User ID : {}, Request Time : {}, URL : {}, RequestBody : {}", userId, LocalDateTime.now(), request.getRequestURL(), requestBody); // 원래 메소드 실행 Object result = joinPoint.proceed(); String responseBody = getResponseBody(wrappedResponse); log.info("API Response Log - User ID : {}, ResponseBody : {}", userId, responseBody); return result; } // 로깅에 Json 형식으로 출력하기 위해 requestBody / responseBody를 Json으로 변환하는 로직 private String getRequestBody(ContentCachingRequestWrapper request) throws IOException { // 생략 } private String getResponseBody(ContentCachingResponseWrapper response) throws IOException { // 생략 } @Pointcut("execution(* org.example.domain.user.controller.UserAdminController.adminMethodA(..))") private void adminMethodA() { } @Pointcut("execution(* org.example.domain.comment.controller.CommentAdminController.adminMethodB(..))") private void adminMethodB() { } }
Admin 사용자만 접근 가능한 API를 실행하면 전후에 로깅은 문제 없이 출력됐다. 그런데 RequestBody가 빈 값으로 출력되는 문제가 있었다.(반환 타입이 void인 API이기 때문에 ResponseBody는 빈 값으로 출력되는게 정상이다.)
RequestBody 값은 왜 비어있을까?
API를 실행하면 Postman에서도 200 응답이기 때문에 API가 요청 / 응답 자체에 문제가 있는 것은 아닌 것 같았다. 그래서 요청을 보냈을 때부터 API가 실행되기 직전(현재 설정해놓은 AOP의 적용 시점이 API 호출 전 / 후이기 때문에)까지의 과정을 알아볼 필요가 있었다. HttpSevletRequest는 ServletRequest를 상속 받고 있는데 ServletRequest에 getInputStream()이라는 메소드가 있었다.
getInputStream()은 ServletInputStream 타입인데 톰캣의 공식 문서를 확인해보면 다음과 같은 내용이 있다.
Provides an input stream for reading binary data from a client request, including an efficient readLine method for reading data one line at a time. With some protocols, such as HTTP POST and PUT, a ServletInputStream object can be used to read data sent from the client. A ServletInputStream object is normally retrieved via the ServletRequest.getInputStream() method. This is an abstract class that a servlet container implements. Subclasses of this class must implement the java.io.InputStream.read() method.
클라이언트의 요청을 읽기 위해 제공 되는 InputStream이라는 것인데, InputStream은 데이터를 읽어들이는 통로로서 한 번 사용하면 없어진다. 그러면 위에서 작성한 AOP에 도달하기 전에 어디선가 요청을 읽어들였다는 의미가 된다. Json 형태로 요청을 보냈다고 가정한다면 다음과 같은 처리 과정을 거치게 된다.
DispatcherServlet 👇 HandlerAdapter 👇 HttpMessageConverter(요청 소비) 👇 AOP(예시에선 AdminApiLogging) 👇 Controller
그림엔 나타나 있지 않지만 빨간 네모로 표시된 부분에서 HttpMessageConverter가 Json 요청을 자바 객체로 변환하기 위해 InputStream을 사용한다. 지금은 요청이 Json 형태라고 가정했기 때문에 MappingJackson2HttpMessageConverter가 InputStream을 사용하게 된다. 그리고나서 컨트롤러 호출 직전에 AOP가 실행되는데 이미 사용되고 없는 요청을 읽으니 빈 값이 출력되고 있었던 것이다.
어떻게 해야 여러 번 쓸 수 있을까?
로그에 빈 값이 출력되고 있는 원인을 알았으니 해결책을 찾아야 하는데 이미 스프링에 답이 있었다. ContentCachingRequestWrapper와 ContentCachingResponseWrapper인데, 내용을 살펴보면 다음과 같다.
HttpServletRequest wrapper that caches all content read from the input stream and reader, and allows this content to be retrieved via a byte array. This class acts as an interceptor that only caches content as it is being read but otherwise does not cause content to be read. That means if the request content is not consumed, then the content is not cached, and cannot be retrieved via getContentAsByteArray(). Used, for example, by AbstractRequestLoggingFilter.
getContentAsByteArray()와 같은 메소드를 통해 InputStream을 소비하면 내부의 byte 배열에 캐싱하는데, 이렇게 캐싱된 요청 데이터는 몇 번이고 사용할 수 있게 되는 것이다.
그럼 어디에서 캐싱해야 할까?
요청 데이터는 스프링 내부에서 계속 사용될테니 클라이언트와의 연결점에서 가장 최전선에 있는 필터에서 캐싱을 하는 것이 좋다고 생각했다. 그래서 아래와 같이 요청과 응답을 캐싱하는 필터를 추가주었다.
@Component public class ContentCachingFilter implements Filter { @Override public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException { HttpServletRequest wrappedRequest = new ContentCachingRequestWrapper((HttpServletRequest) servletRequest); HttpServletResponse wrappedResponse = new ContentCachingResponseWrapper((HttpServletResponse) servletResponse); try { filterChain.doFilter(wrappedRequest, wrappedResponse); } finally { ((ContentCachingResponseWrapper) wrappedResponse).copyBodyToResponse(); } } }
필터를 추가하면 다음과 같은 처리 과정을 거치게 된다.
ContentCachingFilter(요청을 소비하고 캐싱) 👇 DispatcherServlet 👇 HandlerAdapter 👇 HttpMessageConverter 👇 AOP(예시에선 AdminApiLogging) 👇 Controller
API 로깅에 다시 출력해보자
사용자가 보낸 요청을 필터에서 사용하고 캐싱했기 때문에 이후의 처리 과정에서는 캐싱한 요청 데이터를 사용하면 된다. 지금 작성해 놓은 API 로깅 코드에서는 캐싱한 요청 데이터를 사용하고 있지 않기 때문에 수정이 필요하다.
@Slf4j @Aspect @Component @RequiredArgsConstructor public class AdminApiLogging { private final ObjectMapper objectMapper; @Around("adminMethodA() || adminMethodB()") public Object adminApiLogging(ProceedingJoinPoint joinPoint) throws Throwable { HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest(); HttpServletResponse response = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getResponse(); String requestBody = getRequestBody((ContentCachingRequestWrapper) request); Long userId = (Long) request.getAttribute("userId"); log.info("API Request Log - User ID : {}, Request Time : {}, URL : {}, RequestBody : {}", userId, LocalDateTime.now(), request.getRequestURL(), requestBody); // 원래 메소드 실행 Object result = joinPoint.proceed(); String responseBody = getResponseBody((ContentCachingResponseWrapper) response); log.info("API Response Log - User ID : {}, ResponseBody : {}", userId, responseBody); return result; } // 로깅에 Json 형식으로 출력하기 위해 requestBody / responseBody를 Json으로 변환하는 로직 private String getRequestBody(ContentCachingRequestWrapper request) throws IOException { // 생략 } private String getResponseBody(ContentCachingResponseWrapper response) throws IOException { // 생략 } @Pointcut("execution(* org.example.domain.user.controller.UserAdminController.adminMethodA(..))") private void adminMethodA() { } @Pointcut("execution(* org.example.domain.comment.controller.CommentAdminController.adminMethodB(..))") private void adminMethodB() { } }
RequestBody도 문제 없이 출력되는 것을 확인할 수 있다. 지금은 Json 형태의 요청이라고 가정하며 만들었기 때문에 Json 이외의 요청, 에러 상황 등에 대해서는 제대로 동작하지 않을 수 있다. 하지만 RequestBody가 왜 빈 값이 출력되는지 알아보는 과정에서 스프링의 구조적인 부분에 대해 공부가 됐기 때문에 추가적인 구현이 필요하다고 해도 조금 더 수월하게 진행할 수 있지 않을까 생각한다.
✅ 출처
Spring AOP란?
https://velog.io/@wnguswn7/Spring-AOPAspect-Oriented-Programming%EB%9E%80HttpServletRequest 여러 번 읽기
https://www.baeldung.com/spring-reading-httpservletrequest-multiple-times
