이 작업은 사실 컨트롤러에는 info, 그 외 메서드 호출에는 debug로 로그를 남기고, 메세지는 “Called {메서드 명} {파라미터} {…}” 형태로 출력한다. 굉장히 단순하지만 그렇기 때문에 까먹고 빠뜨리기 쉬워, 기존에 작업된 메서드에도 많은 부분이 누락되어있고 동일 클래스에도 어떤 메서드는 되어있고 어떤 메서드에는 빠져있는 경우도 있었다. 추가적으로 리팩토링으로 인해 메서드 이름이 바뀌더라도 해당 로그 메세지의 메서드 명에는 반영이 안되어있는 경우도 있었다.

이런 상황을 보면서, 이를 Spring AOP를 통해 애노테이션만 달면 간편하게 메서드명과 파라미터들을 따서 로그 메세지를 찍어주는 애노테이션과 Aspect를 만들어보고자 한다.

Spring AOP로 로깅 및 Web hook으로 디스코드 알림 붙이기

이전에 작업했던 기록을 참고하여 로깅 애노테이션을 작성해보자.

애노테이션 및 Aspect 추가

@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
public @interface Logging {

	LogLevel level() default LogLevel.INFO;
}


// Log Level 값
public enum LogLevel {

	TRACE, DEBUG, INFO, WARN, ERROR
}
Java
복사

이처럼 로깅에 사용할 애노테이션을 추가해주고,

@Slf4j
@Aspect
@Component
@RequiredArgsConstructor
public class LogAspect {

	private final ParameterNameDiscoverer discoverer = new DefaultParameterNameDiscoverer();

	@NotNull
	private static String getClassName(JoinPoint joinPoint) {
		String classPath = joinPoint.getSignature().getDeclaringType().getName();
		String[] classPathSplit = classPath.split("\\.");
		return classPathSplit[classPathSplit.length - 1];
	}

	@Before(value = "@within(logging) || @annotation(logging)", argNames = "joinPoint,logging")
	private void printLog(JoinPoint joinPoint, Logging logging) {
		LogLevel level = logging.level();

		Method method = ((MethodSignature) joinPoint.getSignature()).getMethod();
		String methodName = method.getName();
		Object[] args = joinPoint.getArgs();
		String[] parameterNames = discoverer.getParameterNames(method);

		StringBuilder sb = new StringBuilder();
		sb.append(callerClass).append(" - ");
		sb.append("Called ").append(methodName).append(" ");
		if (Objects.nonNull(parameterNames)) {
			for (int i = 0; i < args.length; i++) {
				sb.append(parameterNames[i]).append(": ").append(args[i]).append(", ");
			}
		}
		sb.delete(sb.length() - 2, sb.length() - 1);
		switch (level) {
			case TRACE:
				log.trace(sb.toString());
				break;
			case DEBUG:
				log.debug(sb.toString());
				break;
			case WARN:
				log.warn(sb.toString());
				break;
			case ERROR:
				log.error(sb.toString());
				break;
			default:
				log.info(sb.toString());
				break;
		}
	}
}
Java
복사

이처럼 Aspect를 작성해주었다. 로깅 동작을 확인해보면,

기존에 이와 같이 출력되던 로그가

이처럼 바뀌어서 출력된다. 다만 문제는 LentController와 같이 클래스 명이 출력되던 부분이, LogAspect로 바뀌어 호출된 메서드 클래스 명을 알 수 없게 되었다.

String[] classPath = joinPoint.getSignature().getDeclaringType().getName().split("\\.");
String callerClass = classPath[classPath.length - 1];
Java
복사

위 코드를 추가해 클래스 명도 같이 출력하도록 수정하였다.

Method 로깅이 동작하지 않는 문제 발생

애노테이션의 타겟 @Target({ElementType.METHOD, ElementType.TYPE})이나 포인트 컷 value = "@within(logging) || @annotation(logging)"를 보면 알 수 있듯, 본래 작성 의도는 로깅을 출력하고자 하는 메서드 혹은 클래스 위에 추가하면 해당 메서드 혹은 클래스 내의 모든 메서드의 호출 시 로깅이 찍히게 하는 것이다.

지금 작성한 코드에서의 동작을 보면,

클래스 위에 추가한 애노테이션의 경우, 이처럼 잘 동작한다.

하지만 이처럼 메서드 위에 붙이게 되면

이처럼 NPE가 발생한다.

더 정확히는 로깅 레벨을 애노테이션의 value로 받아와야하는데, Logging 애노테이션 자체를 못 받아온다.

문제 원인 분석

문제 원인을 알아보기 위해 디버깅을 통해 해당 Logging 값을 가져오는 위치를 찾아보았다.

AspectJExpressionPointcut.class 파일에서 ShadowMatch에서 매칭되는 JoinPoint를 가져오는 부분에서 Logging 객체를 받아온다.

이 때 받아오는 값을 비교해보면,

이처럼 성공할 때에는 binding으로 Logging 값을 잘 가져오지만, 실패할 때는 binding에 null을 들고온다.

Pointcut에 binding 해주는 부분을 찾아보자. 이 때의 동작은 애플리케이션 시작 시에 ShadowMatch에 AOP 애노테이션들을 순회하며 파라미터들을 미리 등록해 놓은 후, 이후 해당 애노테이션이 사용될 때 ShadowMatch에서 맞는 파라미터 값을 꺼내 binding으로 같이 반환한다.

위는 ShadowMatchImpl.class의 binding으로 묶어주는 부분이고

맞는 파라미터는 이처럼 switch 문으로 var의 타입에 맞춰 꺼내온다.

메서드에 추가한 Logging 애노테이션의 경우에는 getAnnotationFromMember를 통해 꺼내오는데,

애노테이션의 이름을 들고 리플랙션으로 애노테이션 클래스를 가져와 해당 클래스가 등록한 애노테이션과 타입이 일치하면 애노테이션을 반환한다.

이 때의 리플랙션으로 가져오는 애노테이션과 AccessibleObject 값을 비교해보자.

먼저 가져오는 애노테이션의 경우 큰 차이는 없어보인다. 하지만 AccessibleObject의 경우에는

성공 시에는 이처럼 declearedAnnotations에 작성한 Logging 애노테이션과 레벨이 잘 들어있는데,

실패 시에는 declearedAnnotations에 작성한 애노테이션이 들어있지 않았다.

아까 애플리케이션 시작 시 애노테이션을 순회하면서 ShadowMatch에 파라미터를 등록한다고 했는데, 그럼 저 aMember라는 값이 등록되는 시점을 찾아가보자.

이처럼 aMember를 등록하는 곳을 찾아와, 디버깅 조건을 추가해 원하는 시점을 찾아냈다.

마찬가지로 delcaredAnnotations가 성공 시에는 가진 채로 주입되고, 실패 시에는 없이 주입된다.

그럼 주입해주는 곳을 역순으로 타고 올라가며 찾아가보자.

이처럼 AopUtils.class에서 canApply 메서드를 호출 시 메서드와 클래스를 넘겨 등록하게 된다.

그럼 등록 시점에서의 값을 확인해보기 위해 조건을 걸어 디버깅 중단점을 추가하여 데이터를 확인 해보면,

마찬가지로 getAllDeclaredMethods로 가져온 메서드들 중 Logging 애노테이션을 달아둔 메서드를 확인해보면 declaredAnnotations에 없는 것을 볼 수 있다.

그럼 애초에 주입부터 잘못된 거니까 어쩔 수 없는 걸까?

@Before(value = "@within(logging)", argNames = "joinPoint,logging")
Java
복사

하지만 포인트 컷에 컨트롤러 조건만 추가한 후 다시 동작 시켜보면 잘 동작한다.

디버깅을 통해 @within(logging) 조건과 @within(logging) || @annotation(logging) 조건의 차이를 찾아보자.

기존의 과정을 다시 반복하며 이전과 다르게 처리되는 부분을 찾아보니, shadowMatch에서 var 타입에 맞춰 애노테이션을 꺼내오는 과정이 달랐다.

기존의 포인트 컷에서는 var 타입이 8이고 aMember를 AccessibleObject로 변환하여 애노테이션을 확인하지만,

새로운 포인트 컷에서는 var 타입이 6이고 aClass를 통해서 애노테이션을 확인한다.

애노테이션을 확인하는 내부의 로직을 보면,

•

메서드 방식

•

컨트롤러 방식

이처럼 추상화 되어 있어 구체적으로 내부를 확인할 수 없었다.

또 다른 차이점으로는

aClass의 경우에는 이처럼 annotationData에 Logging 클래스가 들어있다.

여기까지의 정보를 통해 그 원인을 추측해보자면, @within의 경우에는 getAnnotationFromClass에서 애노테이션을 확인 할 때 aClass의 annotationData에 해당 클래스가 있는 지 확인하고, @annotation의 경우에는 getAnnotationFromMember에서 애노테이션을 확인할 때 aMember의 declaredAnnotations에서 확인하는 것으로 예상된다.

@within(logging) || @anntation(logging)으로 다시 돌려 놓은 후 위의 파서 로직 부분에서 타입 지정하는 부분에 breakpoint를 걸어 확인해보니,

Logging의 경우 varType을 지정하는 부분에 createWithinAnnotationVar → createAtAnnotationVar으로 두 번 들어온다.

이를 통해 파서에서 포인트 컷을 파싱할 때 앞에 있는 @within을 통해 createWithinAnnotationVar를 호출해 var = 6으로 지정 후, or 조건 뒤의 @annotation 파싱 할 때 createAtAnnotationVar를 호출해 var = 8으로 지정하여 덮어쓰는 것으로 추측된다. 때문에 항상 타입 createAtAnnotationVar로 데이터 가져오기 때문에 메서드 애노테이션은 동작하지만 컨트롤러 애노테이션으로는 데이터가 안가져와 null이 들어가게 되는 것 같다.

추가 확인 및 결론

추측에 근거를 더하기 위해 포인트 컷을 @annotation(logging) || @within(logging)로 바꾸어 동작시키면, 동일한 이유로 클래스 애노테이션만 동작하게 될까를 확인해봤다.

예측했던 대로 메서드 애노테이션의 경우에는 null을 가져온 후 NPE가 발생하고,

클래스 애노테이션은 잘 동작한다.

여기까지 확인한 후 생각을 해보니, 결국 이 문제는 파서의 파싱 방식 문제로 or 방식으로는 해결할 수 없게 느껴졌다.

@Before(value = "@within(logging)", argNames = "joinPoint,logging")
	public void classLogAdvice(JoinPoint joinPoint, Logging logging) {
		printLog(joinPoint, logging);
	}

	@Before(value = "@annotation(logging)", argNames = "joinPoint,logging")
	public void methodLogAdvice(JoinPoint joinPoint, Logging logging) {
		printLog(joinPoint, logging);
	}

	private void printLog(JoinPoint joinPoint, Logging logging) {
		if (logging == null) {
			return;
		}
		LogLevel level = logging.level();

		String[] classPath = joinPoint.getSignature().getDeclaringType().getName().split("\\.");
		String callerClass = classPath[classPath.length - 1];
		Method method = ((MethodSignature) joinPoint.getSignature()).getMethod();
		String methodName = method.getName();
		Object[] args = joinPoint.getArgs();
		String[] parameterNames = discoverer.getParameterNames(method);

		StringBuilder sb = new StringBuilder();
		sb.append(callerClass).append(" - ");
		sb.append("Called ").append(methodName).append(" ");
		if (Objects.nonNull(parameterNames)) {
			for (int i = 0; i < args.length; i++) {
				sb.append(parameterNames[i]).append(": ").append(args[i]).append(", ");
			}
		}
		sb.delete(sb.length() - 2, sb.length() - 1);
		switch (level) {
			case TRACE:
				log.trace(sb.toString());
				break;
			case DEBUG:
				log.debug(sb.toString());
				break;
			case WARN:
				log.warn(sb.toString());
				break;
			case ERROR:
				log.error(sb.toString());
				break;
			default:
				log.info(sb.toString());
				break;
		}
	}
Java
복사

때문에 이처럼 조금 불편하지만 동일한 로직을 클래스와 메서드에 해당하는 서로 다른 Device에 포인트 컷을 각각 달아주었다.

이처럼 각각 잘 동작하는 것도 확인했다.

참고

[Spring 프로젝트] Annotation 동작 원리와 사용법

Annotation 동작 원리와 사용법 Spring Boot를 사용하다 보면 @Component, @Controller, @Repository, @Transactional, @Aspect 등 다양한 어노테이션을 사용하게 된다. 그럼 이런 어노테이션이 실제로는 어떻게 동작하는 것인지, 내가 만약 새로운 어노테이션을 만들어서 사용하고 싶다면 어떻게 하면 되는 것인지에 대해 알아보자. 1. Annotation 이란? 우선 어노테이션 자체는 주석과도 같다. (실제로 번역기를 돌려도 주석으로 나온다.) 즉, 코드 사이에 주석처럼 쓰이면서 특별한 의미, 기능을 수행하도록 하는 기술로 프로그램에게 추가적인 정보를 제공해주는 메타 데이터이다. 2. 어노테이션의 용도 컴파일러에게 코드 작성 문법 에러를 체크하도록 정보를..

https://hirlawldo.tistory.com/43