기존 로그를 스프링 AOP 로 개선하기

개요

---

회사에 로그가 상세하게 기록되지 않아서 오류를 확인하기 힘들었습니다. AOP를 활용해 비지니스 코드에 따로 로그를 작성하지 않고도 원하는 곳에 작성할 수 있도록 개발했습니다.

 

 

기존의 로그 방식

---

Front, Admin 2개의 프로젝트가 있는데 이 중에 Admin 프로젝트는 로그가 아래처럼 각 Controller의 시작시에 찍혀 있습니다. 이는 비지니스 로직에 의미없는 불필요한 코드 추가이며 새로운 메서드가 생성될 때마다 수동으로 작성해야 합니다. 또한 로그 규칙이 변경된다면 모든 메서드의 로그 코드를 수정해야 하는 불편함이 있습니다.

 

클래스명.메서드명으로 모든 시작 위치에 찍혀 있는 로그

 

로그는 각 메서드마다 공통으로 기능이 필요한 부분으로 관점 지향 프로그래밍이 필요합니다. 따라서 스프링 AOP를 사용해서 로그 체계를 새롭게 잡았습니다. 스프링 AOP의 개념과 작동 원리는 아래의 링크를 참고하시길 바랍니다.

 

 

 

 

초기 개발 코드

---

Controller와 Service가 실행될 때 클래스명과 메서드명을 기록하고 싶었습니다. 또한 메서드의 경우에는 작동한 시간도 나타내도록 했습니다.

 

@EnableAspectJAutoProxy
@Configuration
public class ControllerAspectConfig {

}

 

@EnableAspectJAutoProxy로 Aspect 사용이 가능하도록 등록합니다.

 

@Slf4j
@Aspect
@Component
public class ControllerAspect {
	@Pointcut("execution(* com.starmark.controller.*Controller.*(..))")
	public void controllerPointCut() {}
	
	@Pointcut("execution(* com.starmark.service.impl.*ServiceImpl.*(..))")
	public void servicePointCut() {}

	@Before("controllerPointCut()")
	public void logBeforeController(JoinPoint.StaticPart jpsp) {
		log.info("{}.{}", 
        	jpsp.getSignature().getDeclaringType().getName(), jpsp.getSignature().getName());
	}

	@Around("servicePointCut()")
	public Object logAroundServiceImpl(ProceedingJoinPoint joinPoint) throws Throwable {
		log.info("{}.{}",
			joinPoint.getTarget().getClass().getName(), joinPoint.getSignature().getName());

		StopWatch sw = new StopWatch();
		sw.start();
		Object result = joinPoint.proceed();
		sw.stop();
		log.info("MethodName = {}, Service Time : {} ", 
        	joinPoint.getSignature().getName(), sw.getTotalTimeSeconds());
		
		return result;
	}
}

 

@Pointcut으로 모든 *Controller와 *ServiceImpl을 설정합니다.

각 클래스에 있는 모든 메서드를 대상으로하며 접근 제어자와 매개변수는 모두 허용합니다. 

 

*Controller는 시작 로그만 찍습니다. 따라서 @Before로 등록합니다. 

 

*ServiceImpl은 시작 로그와 걸린 시간을 모두 로그로 찍습니다. joinPoint.proceed()를 기준으로 이전에는 @Before로 작동하고 그 이후는 @After로 작동합니다. StopWatch를 이용해 joinPoint.proceed()를 위아래로 sw.start()와 sw.stop()으로 감쌌습니다.

 

결과는 아래와 같습니다.

 

Controller와 Service 로그

 

 MainController 클래스의 index 메서드가 실행되어 MainServiceImpl 클래스의 selectNoticePopupList 메서드가 실행된 것을 알 수 있습니다. 또한 해당 메서드는 0.098초가 걸렸습니다. 이제 비지니스 로직의 흐름을 쫓아가기가 훨씬 수월해졌습니다.

 

 

한계와 개선점

---

• 내부 호출을 외부 호출로 바꾸어 스프링 AOP 적용하기

 스프링 AOP의 한계는 같은 클래스 내의 내부 호출은 로그가 찍히지 않습니다. 이유는 프록시를 통한 호출이 아니라 직접 호출이기 때문입니다. 문제가 되는 코드는 아래와 같이 내부호출을 하는 4개의 메서드 입니다. 결제내역,  승인내역, 주문상품정보, 주문상태는 중요한 내용이기 때문에 로그가 필요했습니다. 

 

public int insertLumpSum() {
...
// 1. 주문결제내역(헤더)
resultInt += insertPayH(payHVo);

// 2. 승인내역
resultInt += insertPayA(payAVo);

// 3.주문상품
resultInt += insertPayP(payPVo);

// 4. 주문상태
resultInt += insertPayStatus(payStatusVo);
...
}

 

 해결할 수 있는 방법은 여러가지가 있는데 가장 좋은 방법은 별도의 클래스로 정의해서 호출하는 것입니다. 별도의 클래스로 호출하면 다시 프록시를 통해 호출되기 때문에 정상적으로 로그가 찍힙니다. 위의 코드는 서비스 클래스에 정의되어 있는데 별도의 서비스 클래스를 만들지 않고 바로 repository에서 호출하는 방법을 택했습니다. 어차피 각 메서드는 repository에 저장하는 역할만 하고 있습니다. 따라서 좀 더 손쉽게 문제를 바로 해결했습니다.

 

기존 내부호출을 외부 호출로 전환하여 스프링 AOP 한계 극복

 

 

 

정리

---

 스프링 AOP를 활용하여 원하는 위치에 로그를 찍도록 개선했습니다. 관점지향 프로그램으로 별도의 클래스에 코드를 정의해서 적용해보았습니다. 수동으로 했으면 엄청 복잡했을 일들을 스프링 AOP를 활용해 쉽게 해결할 수 있었습니다.

 

 프록시를 통해 작업하는 원리와 Adviser에 Advice와 Pointcut을 등록해서 사용하며 여러개를 등록 할 수 있는 개념도 배웠습니다.