AOP를 이용하여 API 로깅하기 (RequestBody, ResponseBody)

AOP

• 관점 지향 프로그래밍
• 반복되고 공통적으로 사용되는 부분을 분리
• 부가적인 기능을 핵심 로직으로부터 분리하여 핵심로직은 오로지 자신에게만 집중할 수 있음

 

발생한 문제 : NPE

LogAspect를 모두 작성하고 실행하려고 하는데 NullPointerException이 발생했다

Caused by: java.lang.NullPointerException: null

 

첫 번째 시도 : HttpServletRequest 수정

HttpServletRequest를 불러오는 부분에서 문제가 있었나 싶어서 해당 부분을 인텔리제이가 추천하는 코드로 변경했다

 

변경 전

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

 

변경 후

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

 

하지만 동일한 에러는 계속 발생했다

 

해결 : Pointcut 수정

기존에 작성했던 포인트컷은 @Pointcut("execution(* ..Admin.(..))") 이다

요구사항에서 로깅을 찍어야 하는 컨트롤러는 모두 이름에 Admin이 들어가야 했기 때문에 저렇게 작성을 해줬는데 뭔가 저 포인트컷의 내용이 모호하게 잡혀있어서 제대로 반영되지 못하고 AOP가 모든 요청에 대해서 실행하는 것 같은 기분이 들었다

그래서 좀 더 명시적으로 포인트컷을 수정했다!

  @Pointcut("execution(* org.example.expert.domain.user.controller.UserAdminController.changeUserRole(..))")
    public void userAdminController() {
    }

   @Pointcut("execution(* org.example.expert.domain.comment.controller.CommentAdminController.CommentAdminController(..))")
    public void commentAdminController() {
    }

 

패키지 경로부터 시작해서 아예 관리자 컨트롤러 내부에 있는 메서드까지 명시하니까 에러가 사라지고 잘 작동했다!

 

 

발생한 문제 : HttpServletRequest의 getInputStream() 호출 시 에러 발생 

requestBody내역을 로그에 찍어야 하기 때문에 LogAspect에서 getInputStream()을 호출하는 코드를 작성했다!

 public String getRequestBody(HttpServletRequest request) throws IOException {
        ObjectMapper objectMapper = new ObjectMapper();
        return objectMapper.readTree(request.getInputStream()).toString();
    }

 

하지만 에러가 발생했다

Request processing failed: java.lang.IllegalStateException: getInputStream() has already been called for this request

 

HTTP 요청에 대해 getInputStream() 메서드를 한 번 이상 호출했을 때 발생하는 에러가 발생한 것이다!

찾아보니 HttpServletRequest에서 Stream형태로 RequestBody에 접근해 데이터를 가져갈경우에 스트림이 소비되면서 딱 한번만 읽을 수 있기 때문에 getInputStream() 또는 getReader()를 호출하면, 스트림이 소비되어 이후 다시 읽을 수 없다는 것이다

AOP를 사용하면서 먼저 RequestBody를 읽어서 스트림을 소비하고, 그 다음에 컨트롤러에서 한번 더 읽으려고 했는데 이미 스트림은 소비된 후라서 발생하게 된 것!!

 

해결 : HttpServletRequest의 Body를 여러번 읽을 수 있도록 바꾸기

RequestWrapper 추가

@Getter
public class RequestWrapper extends HttpServletRequestWrapper {
    // 요청 바디를 저장하는 변수 (다시 읽을 수 있도록 캐싱)
    private final String body;

    public RequestWrapper(HttpServletRequest request) {
        super(request);

        StringBuilder stringBuilder = new StringBuilder();
        try (BufferedReader bufferedReader = request.getReader()) { // 요청 바디를 읽을 BufferedReader 생성
            char[] charBuffer = new char[128]; // 128자씩 읽어올 버퍼 생성
            int bytesRead;
            while ((bytesRead = bufferedReader.read(charBuffer)) > 0) {
                // 읽어온 데이터를 StringBuilder에 추가
                stringBuilder.append(charBuffer, 0, bytesRead);
            }
        } catch (IOException e) {
            // 요청 바디를 읽다가 예외가 발생하면 400 Bad Request 예외 발생
            throw new BadRequestException();
        }

        // 읽은 요청 바디를 문자열로 변환하여 저장
        body = stringBuilder.toString();
    }

    @Override
    public ServletInputStream getInputStream() {
        // 저장된 body 문자열을 ByteArrayInputStream으로 변환 (다시 읽을 수 있도록 함)
        final ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(body.getBytes());

        return new ServletInputStream() {
            @Override
            public boolean isFinished() {
                return false; // 스트림이 끝났는지 여부 (false로 설정하여 계속 읽을 수 있도록 함)
            }

            @Override
            public boolean isReady() {
                return false; // 스트림이 준비되었는지 여부 (false로 설정)
            }

            @Override
            public void setReadListener(ReadListener readListener) {
                throw new UnsupportedOperationException(); // 비동기 읽기 미지원
            }

            @Override
            public int read() {
                return byteArrayInputStream.read(); // 저장된 요청 바디를 한 글자씩 읽어서 반환
            }
        };
    }

    @Override
    public BufferedReader getReader() {
        // getInputStream()을 기반으로 BufferedReader 생성하여 반환 (요청 바디를 여러 번 읽을 수 있도록 함)
        return new BufferedReader(new InputStreamReader(this.getInputStream()));
    }
}

 

필터에 적용

  @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        HttpServletResponse httpResponse = (HttpServletResponse) response;

        request = new RequestWrapper(httpRequest);

 

 

발생한 문제 : HttpServletResponse의 Body조회 불가

응답 객체의 body도 조회해야 했기 때문에 Request의 Body를 조회할 때처럼 유사하게 하면 된다고 생각했다

 

첫 번째 시도 : RequestWrapper 사용 

public class RequestWrapper extends HttpServletRequestWrapper {
    private final String body;  // 요청 본문을 저장할 변수

    public RequestWrapper(HttpServletRequest request) throws IOException {
        super(request);
        StringBuilder stringBuilder = new StringBuilder();
        BufferedReader bufferedReader = request.getReader();
        String line;
        while ((line = bufferedReader.readLine()) != null) {
            stringBuilder.append(line).append("\n");
        }
        body = stringBuilder.toString(); // 본문 저장
    }

    @Override
    public BufferedReader getReader() {
        return new BufferedReader(new InputStreamReader(new ByteArrayInputStream(body.getBytes())));
    }

    @Override
    public ServletInputStream getInputStream() {
        ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(body.getBytes());
        return new ServletInputStream() {
            @Override
            public boolean isFinished() {
                return false;
            }

            @Override
            public boolean isReady() {
                return true;
            }

            @Override
            public void setReadListener(ReadListener readListener) {}

            @Override
            public int read() {
                return byteArrayInputStream.read();
            }
        };
    }

    public String getBody() {
        return body;
    }
}

 

필터 적용

@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
    HttpServletRequest httpRequest = (HttpServletRequest) request;
    HttpServletResponse httpResponse = (HttpServletResponse) response;

    RequestWrapper requestWrapper = new RequestWrapper(httpRequest);
    chain.doFilter(requestWrapper, httpResponse);
}

 

하지만 로그를 찍어보니 body는 공백으로 나왔다

한참동안 이 방법으로 해결하기 위해서 수많은 삽질을 했다 😂

 

두 번째 시도 : returning = "returnObj" 사용해보기 (안될 것 같긴 했음..)

다른 예시들을 찾아보니 returning = "returnObj"를 사용하여 응답객체를 받아와서 출력하도록 했다

그래서 이 방법으로 응답객체를 출력하기 위해서 시도해봤다

(하지만 그 예시는 @AfterReturning이긴 했다..ㅎㅎ)

(그래도 @Around도 실행 전후에 발생시키는 거니까 응답객체를 사용할 수 있지 않을까하는 일말의 희망으로 사용해봤다.,.)

@Around("userAdminController() || commentAdminController()", returning = "returnObj")
public Object logging(ProceedingJoinPoint joinPoint, Object returnObj) throws Throwable {

@Around("userAdminController() || commentAdminController()")
public Object logging(ProceedingJoinPoint joinPoint, @Return("returnObj") Object returnObj) throws Throwable

 

하지만 인텔리제이에서 빨간줄이 뜨면서 실행할 수 없었다..ㅎㅎ

자세하게 이해하지 못하고 이것저것 끌어서 사용하려니 이런 불상사가 발생한 것이다!

하지만 이것 저것 해봐도 계속 실패했기에 이런거라도 시도해보고 싶었다..

 

해결  :  joinPoint.proceed()의 return 객체로 조회하기

여러번의 시도를 해봤지만 응답객체의 바디값은 나오지 않았고.. 시도했던 이상한 중구난방 클래스들과 메서드들을 모두 지우고 처음부터 다시 찾아보기로 마음을 잡았다

사실 저 첫 번째 시도때 사용했던 코드들은 이해가 잘 되지 않았다 (gpt에게 냅다 물어봐서 얻은 코드이기 때문..)

이걸 쓰면서도 이게 뭔지도 모르고 자꾸 에러나고 하라는대로 하면서 계속 삽질을 했기 때문이다

다시 구글링을 열심히 하면서 찾아본 결과!!

// 메서드 실행
Object result = joinPoint.proceed();

 

이 result객체가 메서드를 실행한 이후의 응답 객체라는 것이다!!!!

엥?? 그러면 그냥

// 메서드 실행
Object result = joinPoint.proceed();

// 메서드 실행 후
LocalDateTime responseTime = LocalDateTime.now();
String responseBody = getResponseBody(result);

 

이러면 되는거 아닌가?

 

실행결과 responseBody값이 드디어 나와 주었다!!😳❤️❤️🥳🩷

 

API 로깅 전체 코드

LogAspect

@Aspect
@Slf4j
@Component
@RequiredArgsConstructor
public class LogAspect {

    @Pointcut("execution(* org.example.expert.domain.user.controller.UserAdminController.changeUserRole(..))")
    public void userAdminController() {
    }

    @Pointcut("execution(* org.example.expert.domain.comment.controller.CommentAdminController.CommentAdminController(..))")
    public void commentAdminController() {
    }

    @Around("userAdminController() || commentAdminController()")
    public Object logging(ProceedingJoinPoint joinPoint) throws Throwable {
        // 메서드 실행 전
        Class clazz = joinPoint.getTarget().getClass();
        Logger logger = LoggerFactory.getLogger(clazz);
        HttpServletRequest request = ((ServletRequestAttributes) Objects.requireNonNull(RequestContextHolder.getRequestAttributes())).getRequest();
        HttpServletResponse response = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getResponse();
        Long userId = (Long) request.getAttribute("userId");
        LocalDateTime requestTime = LocalDateTime.now();
        String requestBody = getRequestBody(request);
        Map<String, Object> params = new HashMap<>();

        try{
            String decodedURL = URLDecoder.decode(request.getRequestURI(), "UTF-8");
            params.put("userId", userId);
            params.put("requestTime", requestTime);
            params.put("requestUrl", decodedURL);
            params.put("requestBody", requestBody);
        }catch (Exception e) {
            logger.error("LoggerAspect error", e);
        }

        log.info("Request - User : {} | Time : {} | Url : {} | Body : {}",
                params.get("userId"),
                params.get("requestTime"),
                params.get("requestUrl"),
                params.get("requestBody"));

        // 메서드 실행
        Object result = joinPoint.proceed();

        // 메서드 실행 후
        LocalDateTime responseTime = LocalDateTime.now();
        String responseBody = getResponseBody(result);

        params.put("responseTime", responseTime);
        params.put("responseBody", responseBody);

        log.info("Response - User : {} | Time : {} | Url : {} | Body : {}",
                params.get("userId"),
                params.get("responseTime"),
                params.get("requestUrl"),
                params.get("responseBody"));

        return result;
    }

    private static String getResponseBody(Object result) {
        ObjectMapper objectMapper = new ObjectMapper();
        JsonNode resultNode = objectMapper.valueToTree(result);
        JsonNode bodyNode = resultNode.path("body");
        return bodyNode.toString();
    }

    public String getRequestBody(HttpServletRequest request) throws IOException {
        ObjectMapper objectMapper = new ObjectMapper();
        return objectMapper.readTree(request.getInputStream()).toString();
    }

}

 

Filter

@RequiredArgsConstructor
public class JwtFilter implements Filter {

    private final JwtUtil jwtUtil;

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
        Filter.super.init(filterConfig);
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest httpRequest = (HttpServletRequest) request;
        HttpServletResponse httpResponse = (HttpServletResponse) response;

        request = new RequestWrapper(httpRequest); // 여기서 요청 객체 저장(캐싱)하기

       
 }

 

 

느낀점

• 응답 body를 출력하기 위해서 구글링을 하던 도중 내가 원하는 자료가 많이 보이지 않아서 그냥 gpt에게 물어보면서 해결하려 했는데(첫 번째 시도 : RequestWrapper 사용 부분), 무슨 코드인지도 모르는 상태에서 계속 질문하고 답은 안되고 뱅글뱅글 반복하면서 시간을 너무 허비한 것 같았다..
• 사실 gpt를 사용해서 코드를 짜는 걸 별로 좋아하지 않는데 (내가 짠 코드도 아니고 이게 뭔지도 모르면서 쓰는 것도 찝찝하고 감당이 안되서.. ) 역시 직접적인 문제해결은 내가 일단 이해하고 뭔지 안 다음에 되는 것 같다는 생각이 들었다
• Object result = joinPoint.proceed();이것만 잠시 생각해 봐도 금방 해결할 수 있는 문제를 오히려 gpt를 사용하면서 더 헛수고를 하게 된 것이다..!!!
• 지금 단계에서는 역시 내가 감당하고 이해할 수 있는 코드만 만들고 gpt를 사용한 문제해결을 최대한 지양해야겠다는 생각이 더 들게 됐다

결론 : 문제 해결을 구글링이나 자료보고 생각해보고 하기!