이번 시간에는 AOP를 활용하여 controller - service - repository흐름을 로그로 찍어주는 로그 추적기 기능을 추가해 보도록 하겠습니다.

요청 및 응답 흐름을 한눈에 파악하기 위해 다음 정보를 찍어주고 있습니다.

• UUID 앞 8자리(요청 구분)
• 클래스 명
• 함수 명
• 실행 시간

적용

build.gradle

implementation 'org.springframework.boot:spring-boot-starter-aop' // aop

TraceId

import java.util.UUID;

public class TraceId {

    private String id;
    private int level;

    public TraceId() {
        this.id = createId();
        this.level = 0;
    }

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

    private String createId() {
        return UUID.randomUUID().toString().substring(0, 8);
    }

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

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

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

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

TraceStatus

public class TraceStatus {

    private TraceId traceId;
    private Long startTimeMs;
    private String message;

    public TraceStatus(TraceId traceId, Long startTimeMs, String message) {
        this.traceId = traceId;
        this.startTimeMs = startTimeMs;
        this.message = message;
    }

    public Long getStartTimeMs() {
        return startTimeMs;
    }

    public String getMessage() {
        return message;
    }

    public TraceId getTraceId() {
        return traceId;
    }
}

Trace

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

LogTrace

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

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

    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder.get();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX,
                traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    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.getStartTimeMs();
        TraceId traceId = status.getTraceId();
        if (e == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(),
                    addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
                    resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(),
                    addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs,
                    e.toString());
        }
        releaseTraceId();
    }

    private void syncTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId == null) {
            traceIdHolder.set(new TraceId());
        } else {
            traceIdHolder.set(traceId.createNextId());
        }
    }

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove();//destroy
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }

    private static 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();
    }
}

LogTraceAspect

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

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

    public LogTraceAspect(LogTrace logTrace) {
        this.logTrace = logTrace;
    }

    @Around("execution(* [패키지 명].controller..*(..))" +
            "|| execution(* [패키지 명].service..*(..))" +
            "|| execution(* [패키지 명].repository..*(..))" +
            "|| @annotation([패키지 명].util.trace.Trace)")
    public Object execute(ProceedingJoinPoint joinPoint) throws Throwable {
        TraceStatus status = null;

        // log.info("target={}", joinPoint.getTarget()); //실제 호출 대상
        // log.info("getArgs={}", joinPoint.getArgs()); //전달인자
        // log.info("getSignature={}", joinPoint.getSignature()); //join point 시그니처

        try {
            String message = joinPoint.getSignature().toShortString();
            status = logTrace.begin(message);

            //로직 호출
            Object result = joinPoint.proceed();

            return result;
        } catch (Exception e) {
            logTrace.exception(status, e);
            throw e;
        } finally {
            logTrace.end(status);
        }
    }
}

패키지 명 부분에 해당하는 패키지 경로를 넣어주세요.

테스트

TimeController

@RestController
@RequiredArgsConstructor
public class TimeController {

    private final LogTrace trace;
    private final TimeService timeService;

    @GetMapping("/time")
    public String getCurrentTime() {
            return timeService.getNowTime();
    }
}

TimeService

@Service
@RequiredArgsConstructor
public class TimeService {

    private final LogTrace trace;

    public String getNowTime() {
            LocalDateTime currentTime = LocalDateTime.now();
            DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yy-MM-dd HH:mm:ss");
            return currentTime.format(formatter);
    }
}

테스트용 컨트롤러와 서비스를 추가해 줍시다.

http://localhost:8080/time 으로 접근하면 다음과 같은 로그가 찍히는 것을 확인할 수 있습니다.

@Trace

현재 Aspect는 controller, service, repository 패키지 하위의 모든 메소드를 타겟으로 합니다.

로그추적기의 타겟에 추가하고 싶은 함수가 있다면 해당 어노테이션을 추가해주시면 됩니다.

Reference

• 스프링 핵심 원리 - 고급편(김영한)

김영한님의 강의 내용을 기반으로 작성한 코드입니다.
문제가 된다면 내리도록 하겠습니다.