개요

반복되는 로그 출력 코드를 제거하여 비즈니스 로직에만 집중할 수 있도록 AOP를 활용한 로그 출력 기능을 추가하였다.

Aspect Oriented Programming

관점지향프로그래밍 AOP에 대한 설명은 아래 글을 통해 자세히 알아볼 수 있었다.

https://mangkyu.tistory.com/161

@Before, @After, @AfterThrowing 과 같은 여러 어노테이션이 있어 업무에선 사용하였지만 지금은 간단하게 @Around를 활용하여 컨틀롤러 메서드의 시작과 끝, 서비스 메서드의 끝에서 로그를 출력하도록 구현해보자.

private final ThreadLocal<Integer> stepCounter = ThreadLocal.withInitial(() -> 1);
    
@Around("execution(* com.jhome.user.controller..*(..))")
public Object logController(ProceedingJoinPoint joinPoint) throws Throwable {
	String className = joinPoint.getSignature().getDeclaringType().getSimpleName();
    String methodName = joinPoint.getSignature().getName();
    String fullMethodName = className + "_" + methodName;

	log.info("[{} START] Arguments = {}", fullMethodName, joinPoint.getArgs());
    long startTime = System.currentTimeMillis();

	Object result;
	try {
    	result = joinPoint.proceed();
	} catch (Exception e) {
    	log.error("[{} EXCEPTION] Error: {}", fullMethodName, e.getMessage());
        throw e;
    } finally {
    	stepCounter.remove();
    }

	long endTime = System.currentTimeMillis();
    log.info("[{} END] result = {}, Execution Time: {}ms", fullMethodName, result, endTime - startTime);

	return result;
}

컨트롤러 AOP 이다.

• stepCounter는 메서드 실행 depth 출력을 위해 1부터 시작하는 카운터를 만들었다.
• 시작 시 로그를 출력하며 joinPoint.getArgs()를 활용하여 요청 파라미터를 출력한다.
• 실행시간 기록을 위해 startTime을 기억한다.
• joinPoint.proceed()를 통해 실제 기능을 수행하고 결과를 받는다.
• 이 과정에서 try-catch를 활용하여 예외에 대한 로그도 출력하게 한다.
• try-catch문이 종료되면 stepCounter.remove를 통해 메모리 누수를 방지한다.
• 마지막으로 종료 로그에 실행시간을 출력한다.

@Around("execution(* com.jhome.user.service..*(..))")
public Object logService(ProceedingJoinPoint joinPoint) throws Throwable {
	String className = joinPoint.getSignature().getDeclaringType().getSimpleName();
    String methodName = joinPoint.getSignature().getName();
    String fullMethodName = className + "_" + methodName;

	int currentStep = stepCounter.get(); // 현재 Step 가져오기
    stepCounter.set(currentStep + 1); // Step 증가

	long startTime = System.currentTimeMillis();

	Object result;
    try {
    	result = joinPoint.proceed();
	} catch (Exception e) {
    	log.error("[STEP {}] [{} FAILURE] Error: {}", currentStep, fullMethodName, e.getMessage());
        throw e;
	}

	long endTime = System.currentTimeMillis();
    log.info("[STEP {}] [{} SUCCESS] result = {} ,Execution Time: {}ms", currentStep, fullMethodName, result, endTime - startTime);

	return result;
}

서비스 AOP도 컨트롤러와 크게 다를 것은 없다. step을 찍어주기 위해 step을 증가시켜주고 시작 시 로그는 없이 종료 시 성공/실패를 출력하여 해당 step에서 실패하였음을 로그를 통해 확인하도록 한다.

[UserController_join START] Arguments = [JoinRequest(username=username, password=password)]
[STEP 1] [UserService_isExistUser SUCCESS] result = false ,Execution Time: 431ms
[STEP 2] [UserService_addUser SUCCESS] result = UserResponse(username=username, role=null, type=null, name=null, email=null, phone=null, createAt=2024-11-21 2415:10:27, updateAt=2024-11-21 2415:10:27) ,Execution Time: 788ms
[UserController_join END] result = <201 CREATED Created,ApiResponse(code=0, message=Success, data=UserResponse(username=username, role=null, type=null, name=null, email=null, phone=null, createAt=2024-11-21 2415:10:27, updateAt=2024-11-21 2415:10:27)),[]>, Execution Time: 1232ms

실제 출력된 로그는 이렇다. 케이스 별로 어색한 문장이 있다면 추후 개선해야겠다.
(참고로 같은 클래스 내에서 출력되는 메서드의 경우 로그가 출력되지 않는다.)

이어서

간단하게 AOP 개념을 알아보고 적용해보았는데 크게 어려운 점은 없었다.
로그출력, 실행시간 추적 기능을 추가했는데 트랜잭션 관리 기능도 추가하면 추후 오류 추적에 유용하게 사용할 수 있을 것 같다.
이후 트랜잭션 관리 기능과 출력된 로그를 파일로 저장하는 기능을 구현 해보려고 한다.