[쀼] Spring AOP 사용하여 Logging하기

 

이전에는 각각의 controller 최상단에서 어떤 값을 파라미터로 받았는지 직접 로깅을 진행했다

그리고 실행 시간에 대한 로깅을 하지 않았다.

 

 

비즈니스 코드에 영향을 주지 않으면서도 (log.debug 엄청 많으니까 복잡하더라)

Controller, Service, Repository 메서드 호출할 때마다 시작시간,  끝시간을 남기고 싶었다. 

 

 

따라서, Spring AOP 사용하여 Logging 작업을 진행하기로 했다.

---

대략 이렇게 작성했다

@Aspect
@Component
public class LoggingAspect {
	private static final Logger logger = LoggerFactory.getLogger(LoggingAspect.class);

	// ThreadLocal로 시작 시간을 저장
	private static ThreadLocal<Long> startTimeThreadLocal = new ThreadLocal<>();

	@Pointcut("within(com.exciting.vvue..*) && within(@org.springframework.web.bind.annotation.RestController *)")
	public void controllerMethods() {}

	@Pointcut("within(com.exciting.vvue..*) && within(@org.springframework.stereotype.Service *)")
	public void serviceMethods() {}

	@Pointcut("within(com.exciting.vvue..*) && within(@org.springframework.stereotype.Repository *)")
	public void repositoryMethods() {}

	@Around("controllerMethods() || serviceMethods() || repositoryMethods()")
	public Object logAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
		// 시작 시간을 ThreadLocal에 저장
		long startTime = System.nanoTime();
		startTimeThreadLocal.set(startTime);

		String currentTime = LocalDateTime.now().format(DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS"));
		logger.info("[INFO] [{}] [{}] {} | started with arguments: {}",
			resolvePointcutName(proceedingJoinPoint),
			currentTime,
			proceedingJoinPoint.getSignature().toShortString(),
			proceedingJoinPoint.getArgs());

		try {
			// 실제 메서드 호출
			Object result = proceedingJoinPoint.proceed(); // ProceedingJoinPoint에서 proceed() 호출

			// 메서드 실행 후 종료 시간 계산
			long endTime = System.nanoTime();
			long duration = (endTime - startTime) / 1_000_000; // 밀리초로 변환
			logger.info("[INFO] [{}] [{}] {} | duration: {} ms. Return value: {}",
				resolvePointcutName(proceedingJoinPoint),
				currentTime,
				proceedingJoinPoint.getSignature().toShortString(),
				duration,
				result);

			return result;
		} catch (Throwable throwable) {
			// 예외 발생 시 처리
			long endTime = System.nanoTime();
			long duration = (endTime - startTime) / 1_000_000; // 밀리초로 변환
			logger.error("[ERROR] [{}] [{}] {} | threw exception after {} ms: {}",
				resolvePointcutName(proceedingJoinPoint),
				currentTime,
				proceedingJoinPoint.getSignature().toShortString(),
				duration,
				throwable.getMessage());
			throw throwable;
		} finally {
			// ThreadLocal 값 정리
			startTimeThreadLocal.remove();
		}
	}

	private String resolvePointcutName(ProceedingJoinPoint proceedingJoinPoint) {
		Class<?> clazz = proceedingJoinPoint.getSignature().getDeclaringType();
		Class<?> superClass = clazz.getSuperclass();

		if (clazz.isAnnotationPresent(org.springframework.web.bind.annotation.RestController.class)
			|| superClass != null && superClass.isAnnotationPresent(org.springframework.web.bind.annotation.RestController.class)) {
			return "controller";
		}

		if (clazz.isAnnotationPresent(org.springframework.stereotype.Service.class)
			|| superClass != null && superClass.isAnnotationPresent(org.springframework.stereotype.Service.class)) {
			return "service";
		}

		if (clazz.isAnnotationPresent(org.springframework.stereotype.Repository.class)
			|| superClass != null && superClass.isAnnotationPresent(org.springframework.stereotype.Repository.class)) {
			return "repository";
		}

		return "unknown";
	}
}

로깅 결과는 아래와 같다

 

 

---

만약에 특정 함수에만 로깅을 진행하고 싶다면,  

 

아래와 같이 어노테이션을 작성하고 

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface LogExecuteTime {
}

 

@Aspect
@Component
public class ExecuteTimeAspect {

	@Around("@annotation(LogExecuteTime)") // 어노테이션 기준으로 진행
	public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
		long start = System.currentTimeMillis();
        
		Object result = joinPoint.proceed(); // 실제 실행 
		
        long end = System.currentTimeMillis();
   
		System.out.println((end - start) + "ms");
		return result;
	}
}