요청로깅 AOP로 해야겠다

2022.08.17 - [개발 이야기/Spring] - 아 인터셉터에서 Request Body 로그 찍고싶다..

아 인터셉터에서 Request Body 로그 찍고싶다..

2022.09.26 - [개발 이야기/Spring] - 요청 정보는 서비스 로직 시작 전에 찍어야지..?

요청 정보는 서비스 로직 시작 전에 찍어야지..?

 

위의 두 포스팅에 이어지는 내용..

로깅에 대한 부분을 변경했다는 포스팅만 3개째 올리고 있는데 더 이상 로깅에 대해선 고민하지 않을 것이다..

더 고민한다고 더 좋은 방안이 당장 떠오르지도 않을 것이며, 지금까지 한 고민들도 가성비가 떨어진다고 느낌..

일단 위 포스팅을 기반으로 개선 전의 상황을 설명하자면..

1. 필터에서 HttpServletRequest를 바디를 캐싱할 수 있는 기능을 가진 구현체로 변경했다.

이 작업을 해준 이유는 Interceptor에서 요청에 대한 로그를 찍기 위함인데, RequestBody를 그냥 HttpServletRequest에서 읽으려면 바디의 정보가 InputStream으로 되어있어서 스트림의 특성상 한번 소모해버리면 다시 읽을 수 없기 때문에 캐싱의 기능을 가진 클래스가 필요했다.

2. Interceptor의 preHandle에서 모든 요청에 대한 요청 정보를 로깅한다.

요청 정보를 로깅하는 위치를 Filter가 아닌 Interceptor의 preHandle 메서드에서 찍은 이유를 정리하자면,

• requestBody를 Json형식으로 출력하고 싶었다. objectMapper를 쓰고 싶어서 Spring이 관리하는 영역인 Interceptor에서 찍어야겠다고 생각했다.
• 비즈니스 로직을 타면서 찍는 로그도 발생할텐데, 순서상 요청로그가 먼저 찍히고 비즈니스 로직의 로그가 찍히는게 자연스럽다고 생각했다.

위의 두 이유가 있었다.

근데 저 상황에서 발생하는 문제가 두 가지 있었다.

1. RequestBody가 json형식이 아니라면 ObjectMapper로 json파싱해서 출력하는 부분에서 에러가 발생한다.
2. 보안상 문제가 있는 민감한 데이터를 주고받을 수 있는데, 공통처리를 담당하는 로직인 인터셉터에서 로그를 남기게 되면 보안상의 문제가 발생할 수 있다.

위 문제점을 해소하기 위해 새로운 로깅 전략을 고민했다.

스프링 AOP를 사용해서 로깅하자

AOP를 사용하면 위의 두 가지 문제점을 모두 해소할 수 있었다.

• AOP를 모든 컨트롤러 핸들러 메서드에 적용시키면, 요청에 들어오는 정보를 이미 어플리케이션단에서 정의한 클래스로 핸들링 된 형태로 받을 수 있어서 json 바디이든 아니든 프레임워크가 알아서 파싱해서 인자로 꽂아주기 때문에 파싱에 대한 에러를 신경쓰지 않을 수 있었다.
• AOP의 포인트 컷은 메서드 단위로 실행할지 말지의 조건을 걸게 하고 요청에 대한 전역적인 처리를 하는 필터나 인터셉터보다 정교하기 때문에 민감한 데이터를 다루는 요청만 로깅하지 않도록 핸들링 하는 것이 쉽다.

이러한 이유로 스프링 AOP로 로깅을 하기로 결정했다.

AOP 어드바이저 코드

@Pointcut("@annotation(com.woowacourse.naepyeon.config.logging.trace.annotation.NoLogging)")
private void noLogging() {
}

@Pointcut("execution(public * com.woowacourse.naepyeon.controller..*Controller.*(..))")
private void allController() {
}

@Around("allController() && !noLogging()")
public Object doLogRequest(final ProceedingJoinPoint joinPoint) throws Throwable {
    loggingStatusManager.syncStatus();
    final String taskId = loggingStatusManager.getTaskId();
    final HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes())
            .getRequest();
    final String method = request.getMethod();
    final String requestURI = request.getRequestURI();
    final Object[] args = joinPoint.getArgs();
    log.info("[{}] {} {} args={}", taskId, method, requestURI, args);

    try {
        return joinPoint.proceed();
    } finally {
        loggingStatusManager.release();
    }
}

위와 같은 로직을 타게 됐다. 각 요청마다 taskId를 부여하고

taskId, 요청 method, 요청 uri, 핸들러메서드에 전달된 인자들

위의 4가지 요소들을 핸들러 메서드 실행 전에 출력하도록 했다.

포인트컷 같은 경우는 어플리케이션 개발 단에서 정의한 모든 컨트롤러면서 로깅에서 제외할 메서드마다 달아줄 @NoLogging어노테이션이 달리지 않은 메서드를 지정했다.

AOP방식에서도 발생한 문제점

이러면 핸들러 메서드에 전달된 인자가 기본 toString메서드를 호출해서 내부에 어떤 값을 들고 있는지 찍혀도 알 수 없다는 문제점이 있었다.

위와 같은 이유로 모든 dto 클래스에 toString을 오버라이드 하는 컨벤션을 추가했다.

로깅을 위해서 그걸 정해도 되냐? 하는 의문이 들긴 했었지만 이펙티브 자바 아이템 12 - toString을 항상 재정의하라 에서 근거를 얻었다.

내용을 요약하자면, 객체를 출력하고 싶을 때 기본 toString을 사용하면, 원하는 출력 결과를 얻을 수 없을 것이기 때문에 원하는 폼으로 항상 재정의하라는 내용.

내가 toString을 재정의 하고싶은 이유와 부합했다.

---

최종 정리

요청 정보는 스프링 AOP를 사용해서 로깅하도록 개선했다.

포인트컷의 정교함과, RequestBody 파싱을 프레임워크가 알아서 대신 해준다는 편리성의 장점을 가졌다.

위 과정과 더불어서 DTO클래스들에 toString 메서드를 오버라이드하는 컨벤션을 추가했다.

 

끝