지난 금요일, 프론트와 API 연동을 시작했습니다. 하지만 문제 상황을 해결하기 위해 계속해서 INFO, WARN 여러 레벨의 로그가 기록된 콘솔을 들여다보는 것은 번거로운 일이라는 것을 절실히 느꼈습니다.
따라서 이번 이슈를 해결함으로써 달성하고자 하는 목표는 두 가지 입니다.
이를 통해 클라이언트로부터의 요청에 응답하는 과정에서 어떤 문제가 발생했는지 훨씬 쉽게 파악할 수 있을 것이라 기대합니다.
프로젝트 초기, 예외 상황에 대해서는 AOP를 통해 로그를 남기는 것으로 계획하였습니다. 그러나 이번에 프론트엔드와 연동을 진행하며 어떤 요청이 들어왔는지에 대해 파악할 필요성을 느꼈습니다. 따라서 API 요청에 대해서도 디버그 용도의 로그를 남기기로 결정하였습니다.
AOP를 사용하는 것은 결정되었으니 우리가 사용할만한 옵션이 무엇인지 결정해야 합니다. AOP에 대한 용어 정리는 블로그 게시글을 참고해주세요.
스프링 AOP는 작성한 부가 로직이 언제 사용될지 결정할 수 있는 다양한 종류의 어드바이스를 제공합니다. 저희가 적용되길 원하는 시점은 1. 예외가 터졌을 때, 2. 클라이언트 요청이 들어왔을 때 입니다. 따라서 사용할 수 있는 어드바이스로 메서드가 예외를 던지는 경우 실행되는 @AfterReturning과 메서드 호출 전 후에 수행되는 @Around가 적절하다고 생각합니다.
각각의 AOP가 적용될 시점인 포인트 컷으로는 예외 로깅의 경우 서비스 빈들을, 클라이언트 요청 로깅의 경우 컨트롤로 빈들을 지정할 것입니다.
이러한 조건에 따라 구현한 로그 aspect는 다음과 같습니다.
@Slf4j
@Aspect
@Component
public class LogAspect {
@Pointcut("bean(*Service)")
private void allService(){}
@Pointcut("bean(*Controller)")
private void allRequest(){}
@AfterThrowing(pointcut = "allService()", throwing = "ex")
private void logException(JoinPoint joinPoint, RuntimeException ex) {
String exName = ex.getClass().getSimpleName();
String exMessage = ex.getMessage();
String methodName = joinPoint.getSignature().toShortString();
Object[] args = joinPoint.getArgs();
log.warn("[Ex] {} exName=[{}] exMessage=[{}] args=[{}]",
methodName, exName, exMessage, args);
}
@Around("allRequest()")
private Object logRequest(ProceedingJoinPoint joinPoint) throws Throwable {
long beforeRequest = System.currentTimeMillis();
String methodName = joinPoint.getSignature().toShortString();
Object result = joinPoint.proceed();
long timeTaken = System.currentTimeMillis() - beforeRequest;
log.debug("[Request] {} time=[{}ms]", methodName, timeTaken);
return result;
}
}
예외의 경우는 WARN 레벨로 지정해서 메서드 이름과 예외 이름, 예외 메시지, 전달된 인자들을 로그로 남깁니다. 예외가 터졌을 때 예외 메시지와 인자들을 함께 기록하여 예외의 원인이 무엇인지 조금 더 쉽게 파악할 수 있을 것입니다.
클라이언트 요청의 경우 DEBUG 레벨로 지정하여 실행된 메서드와 걸린 시간만 간단히 기록합니다. 인자들도 함께 기록하면 좋을 것 같으나 게시글 내용 또는 이미지와 같이 인자의 길이가 너무 긴 경우가 있을 거라 생각했습니다. 이 경우 오히려 로그를 확인하기 어려울 것 같아 인자는 따로 기록하지 않기로 했습니다.
실행 시 둘 모두 잘 작동하는 것을 확인할 수 있었습니다.
