Spring AOP @Aspect를 활용하여 Logging 기능을 적용해보자.

 

서론

 

이 포스팅은 배움을 토대로 실제 개발중인 프로젝트에 Spring AOP를 사용한 로깅 기능을 어떻게 구현했는지에 대한 내용입니다. 그리고 그 배움은 김영한 선생님의 '스프링 핵심원리 - 고급편' 강좌를 참고하였습니다.

 

목표

 

구현하고자 한 기능은 다음과 같습니다.

• 호출한 메소드를 계층 별 순서에 맞게 화살표와 띄어쓰기를 통해 구분한다.
• 계층 별 메소드 호출 시작부터 종료까지의 시간을 구한다.
• 메소드 파라미터를 함께 표시한다.
• hibernate 구현 쿼리문을 출력한다.
• 예외 발생 시 별도 표시와 함께 예외 메시지를 출력한다.
• log의 형태는 다음과 같다.

INFO 12-16 17:29:18 [788ecafc] |--> WorkPlanController.getWorkPlanList(WorkPlanSearch(stDate=2024-12-16, mg=0, yjSam3=1, sort=0, sales=0, sam3=1))
INFO 12-16 17:29:18 [788ecafc] | |--> WorkPlanService.findSpYjSelect(WorkPlanSearch(stDate=2024-12-16, mg=0, yjSam3=1, sort=0, sales=0, sam3=1)) Hibernate: {call SP_YJ_SELECT(?,?,?,?,?,?,?)}
INFO 12-16 17:29:18 [788ecafc] | |<-- WorkPlanService.findSpYjSelect(WorkPlanSearch(stDate=2024-12-16, mg=0, yjSam3=1, sort=0, sales=0, sam3=1)) time=49ms
INFO 12-16 17:29:18 [788ecafc] | |--> WorkPlanService.findSpYjSilo1() Hibernate: {call SP_YJ_SILO1()}
INFO 12-16 17:29:18 [788ecafc] | |<-- WorkPlanService.findSpYjSilo1() time=3ms
INFO 12-16 17:29:18 [788ecafc] | |--> WorkPlanService.findSpYjSilo2() Hibernate: {call SP_YJ_SILO2()}
INFO 12-16 17:29:18 [788ecafc] | |<-- WorkPlanService.findSpYjSilo2() time=10ms
INFO 12-16 17:29:18 [788ecafc] |<-- WorkPlanController.getWorkPlanList(WorkPlanSearch(stDate=2024-12-16, mg=0, yjSam3=1, sort=0, sales=0, sam3=1)) time=107ms

(해당 로그는 프로시저를 사용했지만 JPA 사용 시 엔티티 매니저가 생성한 쿼리문을 출력합니다.)

 

코드

 

Spring AOP 기능을 사용하려면 라이브러리를 추가해야 합니다.

# pom.xml
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

# gradle
implementation 'org.springframework.boot:spring-boot-starter-aop'​

 

다음과 같이 추가가 가능합니다. 그런데 JPA 나 Spring Security를 사용하고 있다면 해당 라이브러리 안에 AOP 기능이 들어있어 별도로 추가할 필요가 없습니다. JPA의 경우 내부에서 트랜잭션 처리, Spring security는 보안 관련 처리에 사용하고 있기 때문입니다.

 

라이브러리를 추가했다면 AOP를 사용할 수 있는데요. @Aspect 어노테이션이 붙은 클래스를 찾아 advisor를 빈에 적용시킵니다. advisor는 pointcut, advice 두개로 분류합니다. pointcut은 advice를 적용할 범위를 표현식을 통해 구분하는 역할을 합니다. advice는 빈에 적용될 부가 기능 자체이며 프록시 형태로 구현됩니다.

 

AOP를 공부했다면 익숙한 그림일 것입니다. Pointcut은 어디에, advice는 무엇을 적용하냐인 거고 둘을 합친게 Advisor입니다. 스프링 컨테이너는 빈을 생성하는 시점(런타임)에 Aspect를 통해 조건에 맞는 프록시 객체를 생성합니다.

 

클래스 다이어그램은 다음과 같습니다. Aspect 부분인 LoggerAspect와 직접적인 구현부인 LogTrace가 있습니다. LogTrace의 begin(), end(), exception() 메서드를 사용하여 로그를 생성합니다. 그리고 스레드와 계층 별 레벨을 생성하기 위한 TraceId와 begin() 에서 생성하여 end()에 상태를 전달해주기 위한 TraceStatus 객체가 있습니다.

@Aspect
@Slf4j
@Component
@RequiredArgsConstructor
public class LoggerAspect {
    private final LogTrace logTrace;

    @Around("execution(* your.folder.path.service..*(..))" +
        "|| execution(* your.folder.path..*Controller.*(..))" +
        "|| execution(* your.folder.path.repository..*(..))")
    public Object logExecution(ProceedingJoinPoint joinPoint) throws Throwable {
        TraceStatus status = null;
        try {
            String methodSignature = createMethodSignature(joinPoint);
            status = logTrace.begin(methodSignature);
            Object result = joinPoint.proceed();
            logTrace.end(status);
            return result;
        } catch (Exception e) {
            logTrace.exception(status, e);
            throw e;
        }
    }
    
	...

AOP 적용할 클래스를 @Aspect 어노테이션을 사용하여 구현해주었습니다. 그리고 로깅 기능을 구현한 클래스 LogTrace를 lombok을 사용해 생성자 주입하였습니다. 빈으로 생성하기 위한 @Component 도 했습니다. 혹은 config class 에서 직접 객체를 생성할 수 있습니다.

 

@Around 어노테이션은 Pointcut을 설정하는 부분입니다. 해당 표현식은 controller, service, repository 하위 모든 클래스를 범위로 제한합니다. 그리고 logExecution 메소드가 advisor 부분입니다. spring은 ProceedingJoinPoint라는 객체를 제공하는데 여기서 여러가지 메타 데이터들을 가져올 수 있습니다. 저는 createMethodSignature() 라는 내부 메소드를 통해 가져오고 싶은 것들을 정리해주었습니다.

 

...
// 로그에 찍을 클래스와 메소드, 파라미터값
    private String createMethodSignature(ProceedingJoinPoint joinPoint) {
        String className = joinPoint.getSignature().getDeclaringType().getSimpleName();
        String methodName = joinPoint.getSignature().getName();
        String args = Arrays.stream(joinPoint.getArgs())
            .filter(arg -> arg != null 
            // 특정 클래스 제외
            && !arg.getClass().getName().startsWith("org.springframework")
            && !arg.getClass().getName().startsWith("org.apache"))
            .map(arg -> arg.toString())
            .collect(Collectors.joining(", "));
        return className + "." + methodName + "(" + args + ")";
    }
}

 

className은 advisor가 적용될 클래스명, methodName은 메소드명입니다. 그리고 args는 제공되는 파라미터들인데 bindingResult나 request같은 것들은 불필요하여 filter를 사용하여 걸러주었습니다. 이부분은 뭔가 더 최적화할 방법이 있을 것 같아 고민해봐야 할 것 같습니다. 아무튼 제가 가져오고 싶은 dto 객체만 가져와서 값을 뿌려주도록 의도하였습니다.

 

그래서 최종 리턴값은 'className.methodName(fileDto(param1=...))' 와 같은 형태입니다.

 

다음은 LogTrace 부분입니다.

@Slf4j
@Component
public class LogTrace {
    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();
    private final String START_PREFIX = "-->";
    private final String COMPLETE_PREFIX = "<--";
    private final String EX_PREFIX = "<X-";

    public TraceStatus begin(String methodSignature) {
        TraceId traceId = syncTraceId();
        long startTime = System.currentTimeMillis();
        log.info("[{}] {}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()) + methodSignature);
        return new TraceStatus(traceId, startTime, methodSignature);
    }
...

 

TraceId를 ThreadLocal로 생성합니다. 여러 사람이 서비스를 이용할때 스레드 별로 로그를 구분하기 위해서입니다. 또 메서드 호출과 종료, 예외를 구분하기 위한 START_PREFIX, COMPLETE_PREFIX, EX_PREFIX가 있습니다. 이를 사용하여 로그를 찍습니다. (addSpace()는 뒤에서 함께 설명하겠습니다.)

 

메서드 호출 전 호출되는 begin() 에서는 traceId와 시작시간을 위한 startTIme을 만들어 TraceStatus 객체로 리턴합니다. syncTraceId() 에서는 TraceId를 새로 생성하는지, 기존 아이디에서 레벨만 조정하는지 결정하는데요.

 

...
    private TraceId syncTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId == null) {
            // 최초 호출시 새로운 TraceId 생성
            traceId = new TraceId();
        } else {
            traceId = traceId.createNextId();
        }
        traceIdHolder.set(traceId);
        return traceId;
    }
...

 

threadLocal 변수인 traceHolder에서 값을 가져와서 없으면 -> 최초 생성이기 때문에 새 traceId를 생성합니다. 기존에 값이 있다면 기존 아이디에 레벨만 +1 해주는 createNextId() 메서드를 호출합니다. 뒤에 TraceId 클래스를 참고하시면 이해가 쉬우실 겁니다.

 

...
    public void end(TraceStatus status) {
        complete(status, null);
    }

    public void exception(TraceStatus status, Exception e) {
        complete(status, e);
    }

    private void complete(TraceStatus status, Exception e) {
        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTime();
        TraceId traceId = status.getTraceId();
        
        if (e == null) {
            log.info("[{}] {} time={}ms", 
                traceId.getId(), 
                addSpace(COMPLETE_PREFIX, traceId.getLevel()) + status.getMethodSignature(), 
                resultTimeMs);
        } else {
            log.info("[{}] {} time={}ms ex={}", 
                traceId.getId(), 
                addSpace(EX_PREFIX, traceId.getLevel()) + status.getMethodSignature(), 
                resultTimeMs, 
                e.getMessage());
        }

        releaseTraceId();
    }
...

 

end() 와 exception() 은 예외 메시지를 추가로 뿌려준다는 것 외에는 동일한 기능이기 때문에 complete() 메서드를 공통으로 사용합니다.

 

complete() 는 종료시간 - 시작시간을 통한 메서드 호출시간을 체크합니다. 그리고 addSpace() 를 통해 레벨로 구분한 로그 상태를 가독성 좋게 띄워쓰기와 화살표를 사용해 만드는데요. (이는 begin()도 동일합니다.)

 

...
    private String addSpace(String prefix, int level) {
        StringBuilder sb = new StringBuilder();
        for (int i = 0; i < level; i++) {
            sb.append((i == level - 1) ? "|" + prefix + " " : "| ");
        }
        return sb.toString();
    }
...

 

StringBuilder를 사용해 초기레벨인 1레벨일 경우,

begin() = |-->,

end() = |<--,

2레벨~ 일 경우에는,

begin() = | |-->,

end() = | |<--

와 같이 구분합니다. (목표 항목에 있는 결과 로그를 참고하시면 더 이해가 쉽습니다.)

 

다시 complete() 메서드로 돌아오면, 이렇게 addSpace() 를 사용해 로그를 찍은 후 중요한 과정이 하나 남아있습니다. 호출이 끝난 TraceId의 level을 감소시키거나, 완전히 호출이 끝났을 경우 해당 스레드를 제거해줘야 합니다. 이를 releaseTraceId() 메서드를 통해 구현했습니다.

 

...
    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if(traceId == null) {
            return;
        }

        if (traceId.isFirstLevel()) {
            traceIdHolder.remove();
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }
}

 

nullPointerException을 피하기 위한 if문 뒤에, traceId가 레벨 1인지 체크합니다. 레벨이 1이라면 호출했던 메서드가 모두 종료되었다는 뜻이니 thread를 remove 해줍니다. 이 과정을 빼먹으면 나중에 서비스 과정에서 memory leak 등의 오류가 발생하게 되고 험난한 디버깅 과정이 될 수 있으니 체크해줍니다. 그리고 레벨 1이 아니라면 아직 메서드가 모두 종료되지 않았다는 뜻이므로 레벨만 1 감소시켜줍니다.

 

이 과정은 모두 traceId 클래스에 정의되어 있는데요.

 

@Getter
public class TraceId {
    private String id;
    private int level;

    public TraceId() {
        this.id = UUID.randomUUID().toString().substring(0, 8);
        this.level = 1;
    }

    private TraceId(String id, int level) {
        this.id = id;
        this.level = level;
    }

    public TraceId createNextId() {
        return new TraceId(id, level + 1);
    }

    public TraceId createPreviousId() {
        return new TraceId(id, level - 1);
    }

    public boolean isFirstLevel() {
        return level == 1;
    }
}

 

먼저 TraceId 기본 생성은 UUID를 통한 randomId가 됩니다. 그리고 초기 레벨은 1입니다. 변수를 포함한 생성은 내부 클래스에서만 사용할 용도이기 때문에 private 처리 해줍니다. 그리고 레벨 +1,-1을 해주는 createNextId(), createPreviousId() 와 초기레벨을 체크하는 isFirstLevel() 까지 만들어주면 끝입니다.

 

@Getter
@AllArgsConstructor
public class TraceStatus {
    private TraceId traceId;
    private Long startTime;
    private String methodSignature;
}

 

TraceStatus는 begin()의 로그 상태를 end() 에 전파하는데 필요한 변수들을 저장한 클래스입니다. 지금 보니 굳이 롬복에 의존하지 않고 직접 생성자와 getter를 만들어주는게 좋아 보이네요.

 

추가

 

hibernate 쿼리를 보고 싶다면 application 설정이 별도로 필요합니다.

 

# application.yml

jpa:
	properties:
      hibernate:
        dialect: org.hibernate.dialect.SQLServerDialect
        format_sql: true
    show-sql: true
    
# application.properties

jpa.properties.hibernate.dialect=org.hibernate.dialect.SQLServerDialect
jpa.properties.hibernate.format_sql=true
jpa.show-sql=true

 

하지만 운영환경에서는 너무많은 쿼리가 생성되기 때문에 해당 설정은 꺼두는걸 추천합니다.

 

개인적으로 로깅 기능을 새로 만들자마자 jsp에서 ajax 통신을 여러번 하고 있던 버그를 잡을 수 있었습니다. 기존에 단순하게 호출 메서드를 표시하는 기능으로만 사용하다가 가독성을 개선하고 나니 눈에 바로 보였던 것 같습니다.

 

로그는 지속적으로 개선해나가야 하는 기능입니다. 소프트웨어가 발전하고 여러 기능이 추가됨에 따라 크리티컬한 오류, 상대적으로 중요하지 않은 오류가 나뉘기 때문입니다. 그래서 해당 코드도 요구사항에 맞춰, 혹은 부족하다고 생각되는 부분이 있으면 수정해나가는게 좋을 듯 싶습니다.