AOP 적용 트러블 슈팅

트러블슈팅: AOP와 JWT 필터 충돌 문제 해결 과정

---

1. 문제 상황

어드민 사용자만 접근할 수 있는 특정 API에 접근할 때마다, 접근 로그를 기록해야 했습니다. 이 로그에는 사용자 ID, API 요청 시각, 요청 URL, 요청 본문(request body), 응답 본문(response body) 등이 포함되어야 했습니다. 이를 위해 AOP를 적용하고 ServletRequest의 getReader() 메서드를 사용해 StringBuilder와 BufferedReader로 요청 본문을 읽어왔습니다.

그러나 이 코드에서 다음과 같은 Invalid JWT token 오류가 발생했습니다.

Invalid JWT token, 유효하지 않는 JWT 토큰 입니다.

2. 원인 파악

JWT 필터에서도 요청 본문을 확인해야 하는데, getReader()는 요청 본문을 한 번만 읽을 수 있으므로, 이미 본문이 소진된 상태에서 필터에서 오류가 발생한 것입니다. AOP와 JWT 필터가 모두 요청 본문에 안전하게 접근할 수 있는 방법이 필요했습니다.

3. 해결 시도 1: ContentCachingRequestWrapper로 본문 캐싱

먼저, AOP와 JWT 필터가 요청 본문에 여러 번 접근할 수 있도록 ContentCachingRequestWrapper를 사용해 본문을 캐싱했습니다. 이렇게 해서 JWT 필터와 AOP가 본문에 안전하게 접근할 수 있게 되었고, Invalid JWT token 오류는 해결되었습니다.

수정 전 코드:

BufferedReader로 직접 요청 본문을 읽어 한 번만 접근할 수 있었습니다.

private String getRequestBody() {
    try {
        StringBuilder stringBuilder = new StringBuilder();
        BufferedReader bufferedReader = request.getReader();
        String line;
        while ((line = bufferedReader.readLine()) != null) {
            stringBuilder.append(line);
        }
        return stringBuilder.toString();
    } catch (IOException e) {
        log.error("Failed to read request body", e);
        return "Failed to read request body";
    }
}

수정 후 코드:

ContentCachingRequestWrapper로 본문을 캐싱하여 안전하게 여러 번 접근할 수 있도록 수정했습니다.

private String getRequestBody() {
    if (request instanceof ContentCachingRequestWrapper) {
        ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;
        byte[] contentAsByteArray = cachingRequest.getContentAsByteArray();
        return new String(contentAsByteArray, StandardCharsets.UTF_8);
    }
    return "No Request Body";
}

이 수정으로 Invalid JWT token 문제는 해결된 듯 보였으나, 새로운 문제가 발생했습니다.

---

두 번째 문제: Duplicate entry 오류 발생

1. 문제 상황

권한을 변경하는 API를 테스트했을 때, 첫 번째 호출에서는 정상적으로 동작했지만 두 번째 호출부터 Duplicate entry 오류가 발생했습니다.

2024-10-31T19:57:56.595+09:00 ERROR 26680 --- [nio-8080-exec-8] o.h.engine.jdbc.spi.SqlExceptionHelper : Duplicate entry '2' for key 'admin_access_log.UKd3pny2odb3w9xqdubaf10ul3g'
2024-10-31T19:57:56.601+09:00 ERROR 26680 --- [nio-8080-exec-8] org.example.expert.config.JwtFilter : Invalid JWT token, 유효하지 않는 JWT 토큰 입니다.

첫 번째 호출 후 권한이 정상적으로 변경되었으나, 두 번째 호출부터 중복된 userId로 인해 호출이 실패했습니다.

2. 원인 파악

콘솔 로그에 나타난 Duplicate entry 오류는 트랜잭션이 완료되지 않은 상태에서 AOP가 또 한 번 접근 로그를 기록하려 했기 때문에 발생했습니다. userId는 회원가입 시마다 등록되는 고유 ID로 중복될 일이 없어야 했지만, 트랜잭션이 완료되지 않은 상태에서 AOP가 중복 접근을 시도하면서 오류가 발생한 것이었습니다.

문제의 핵심은 AOP 어드바이스의 실행 시점에 있었다

이 문제는 AOP가 메서드 실행 전후로 이중 접근하면서 트랜잭션이 완료되기 전에 접근 로그를 남기려 한 것이 문제였습니다. 결국, 첫 번째 문제에서 발생한 Invalid JWT token 오류 또한 이중 접근 방식으로 인해 발생한 것이었습니다.

---

3. 해결 시도 2: @After 어드바이스로 변경

트랜잭션이 완료된 후에만 접근 로그를 기록할 수 있도록 @After 어드바이스로 변경하여, 메서드 실행이 완료된 후에만 접근 로그가 기록되도록 했습니다. @After로 변경함으로써 userId 중복 문제와 트랜잭션 오류를 방지할 수 있었습니다.

최종 수정 코드:

@Slf4j(topic = "AccessLogger")
@Aspect
@Component
@RequiredArgsConstructor
public class AccessLoggingAop {

    private final HttpServletRequest request;
    private final AccessLogRepository accessLogRepository;
    private final UserRepository userRepository;

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

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

    @After("comment() || user()")
    public Object logAccess(ProceedingJoinPoint joinPoint) throws Throwable {
        // 요청 시각, URL, 본문 정보 수집
        LocalDateTime requestTime = LocalDateTime.now();
        String requestUrl = request.getRequestURI();
        String requestBody = extractRequestBody();

        // 필터에서 설정된 사용자 ID 가져오기
        Long userId = (Long) request.getAttribute("userId");
        Optional<User> user = userRepository.findById(userId);

        // 유저가 없을 경우 로그 경고 후 종료
        if (user.isEmpty()) {
            log.warn("User not found for ID: {}", userId);
            return joinPoint.proceed();
        }

        // 메서드 실행 후 응답 로깅
        Object response = joinPoint.proceed();
        String responseBody = response != null ? response.toString() : "No Response Body";
        
        log.info("요청한 사용자의 ID: {}, API 요청 시각: {}, API 요청 URL: {}, Request Body: {}, Response Body: {}",
                 userId, requestTime, requestUrl, requestBody, responseBody);

        // 접근 로그 저장
        accessLogRepository.save(new AccessLog(user.get(), requestTime, requestUrl, requestBody, responseBody));

        return response;
    }

    private String extractRequestBody() {
        if (request instanceof ContentCachingRequestWrapper cachingRequest) {
            byte[] contentAsByteArray = cachingRequest.getContentAsByteArray();
            return new String(contentAsByteArray, StandardCharsets.UTF_8);
        }
        return "No Request Body";
    }
}

---

최종 결과 요약

1. 문제 1: Invalid JWT token 오류 - 트랜잭션 전후 이중 접근으로 인해 JWT 필터가 본문을 읽지 못함.
   • 해결: ContentCachingRequestWrapper로 본문을 캐싱하여 JWT 필터와 AOP에서 본문에 안전하게 여러 번 접근 가능하게 수정.
2. 문제 2: 권한 변경 API에서 Duplicate entry 오류 발생 - 트랜잭션 완료 전 중복 접근 시도.
   • 해결: @After로 변경하여 트랜잭션 종료 후에만 접근 로그를 기록해 중복 오류 해결.

---

잘못된 어드바이스 선택으로 인한 시행착오

처음 참고한 예제는 API 실행 시간을 기록하기 위한 AOP 예제로, 메서드 전후 접근을 위해 @Around를 사용한 코드였습니다. 그러나 어드민 접근 로그 기록에는 트랜잭션이 끝난 후 실행되는 @After가 더 적합했으며, 단순히 어노테이션을 @After로 변경하는 것만으로 문제를 해결할 수 있었습니다.

이러한 시행착오를 통해 AOP를 적용할 때, 코드의 기능에 맞는 어드바이스 선택이 매우 중요하다는 점을 깨닫게 되었습니다.

---

https://github.com/coldrice99/spring-advanced.git