Custom Log 추적기

@Slf4j
public class FieldLogTrace implements LogTrace {

    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";

    private TraceId traceIdHolder; //traceId 동기화, 동시성 이슈 발생

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

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

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

    @Override
    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 releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null; // 파괴
        } else {
            traceIdHolder = traceIdHolder.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();
    }
}

위의 복잡한 커스텀 로그 추적기가 존재한다. 이 로그 추적기를 Controller, Service, Repository의 모든 메서드에 심을 것이다. 위의 복잡한 로직을 파악하기보다는 핵심에 집중해보자.

위와 같이 로그를 직관적으로 보이게 하는 것이 목적이다. 컨트롤러가 호출하는 서비스, 서비스가 호출하는 리포지토리의 기능들에 대해 모두 로그 추적기를 달아주어 로직의 깊이도 표현하고 로직 성공에 대한 시간도 표기하기 위함이다.

로그는 TraceId라는 객체로 표현되며 관리된다. TraceId는 FieldLogTrace라는 LogTrace(로그 추적기) 인터페이스 구현체에서 필드로 존재하게 된다. 각각의 메서드들(컨트롤러, 서비스, 리포지토리)은 로그 추적기의 TraceId를 변화시킨다.

그리고 로그 추적기는 싱글톤 빈으로 관리된다.

문제

로그 추적기는 싱글톤이기 때문에 컨테이너안에 하나만 존재하게 된다. 이때 여러 스레드가 이 로그 추적기에 접근하여 로그 추적기의 TraceId를 변화시킨다.

만약 A스레드가 TraceId의 레벨을 1올린다면 이는 B스레드가 TraceId에 접근함에 있어서도 공유가 된다는 것이다.

B스레드의 본래 첫번째 목적은 TraceId의 레벨이0인 것을 1로 올리는 것인데 A스레드가 이미 1을 올렸기에 레벨1을 2로 바꾸는 셈이다.

필드의 상태가 두 스레드에 공유됨에 따라 발생하는 흔한 동시성 문제를 구현한 것이다.

ThreadLocal

ThreadLocal은 이름의 느낌처럼 독립된 쓰레드만이 연결된 보관소이다. 싱글톤 빈에 쓰레드 로컬 필드가 존재한다면 싱글톤 빈은 공유를 위한 공간이지만 그 공간속에 개인적인 서브공간을 보장해준다.

즉 쓰레드A가 들어와서 ThreadLocal 필드를 조작하면 이 조작에 대한 상태는 쓰레드A에게만 동기화되는 것이다.

@Slf4j
public class ThreadLocalLogTrace implements 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<>();

TraceId를 한번 감싸 ThreadLocal안에 둔다면 TraceId는 다른 쓰레드의 TraceId에 대해 독립적인 존재가 된다.

TraceId를 꺼내고싶다면 ThreadLocal의 .get()을 사용하고, ThreadLocal에 담고싶다면 .set(TraceId)를 하면 된다.

우리는 사실 이전에도 ThreadLocal을 경험했다. ThreadLocal을 통한 커넥션 풀 관리를 통해 이미 알고있던 개념을 직접 사용하는 수준까지 온 것이다.

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

우리는 여태껏 빈 객체내의 필드에서 다른 빈 객체를 주입할 때 쓰레드 로컬로 감싼 적이 없다. OrderRepository에 대해 생각해보면 좋을 것이다. OrderRepository의 필드에 변할 수 있는 필드가 존재한다면 동시성을 고려해야겠지만 OrderRepository는 int count와 같은 필드를 가지지 않기에 OrderRepository는 동시성에 대해 안전한 것이다.

또한 여러 스레드가 같은 자바 코드 줄을 실행하는 것은 동시에 가능한 부분이다. 동시에 서로 다른 곳에서 코드를 읽는 것과 서로가 상태 값을 공유하는 것은 두 명의 RPG게이머가 같은 게임에 동시에 접속하는 것과 두 명의 RPG게이머가 같은 캐릭터의 상태를 공유하는 것과 같다.

적용

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {

    private final OrderServiceV3 orderService;
    private final LogTrace trace;

    @GetMapping("/v3/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.request()");
            // 비즈니스 로직 시작
            orderService.orderItem(status.getTraceId(), itemId);
            // 비즈니스 로직 종료
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

우리가 만든 LogTrace를 컨트롤러에 적용하는 단계이다. 빈으로 등록한 LogTrace 구현체를 주입받아 해당 컨트롤러 메서드 실행시 로그 기능이 작동하도록 코드를 짰다. orderService로 LogTrace를 넘겨 다음 호출에 있어서도 로그기능이 동작하여 하나의 비즈니스 로직 싸이클이 로그로 남도록 기능하고 있다.

현재 LogTrace는 동시성 문제를 ThreadLocal을 통해 해결했으며, 각 단계의 호출이 연관성있게 코드를 만들어 각 단계의 상황을 관찰할 수 있었다.

하지만 두 가지 문제정도가 존재하는데 일단 비즈니스 로직이 한 줄의 코드인 것에 비해 로그를 처리하는 코드가 매우 복잡하다는 것이다. 로그 기능을 전방위적으로 넣기위해 모든 메서드 레벨에 해당 형식을 작성해야한다.

그렇게 열심히 모든 메서드에 작성했다하더라도 begin, end, exception의 이름이나 아예 근본적인 로그 로직 자체가 바뀐다면 바뀐다면 모든 메서드에 이 변경작업을 수행해야한다.

비즈니스 로직에 해당하는orderService.orderItem(status.getTraceId(), itemId); 부분을 변수처럼, 주입할 수 있으면 좋을 것이다. 분명한 것은 로그 로직은 어떤 메서드에서도 동일하게 형식이 유지된다는 것이다.