스프링 핵심 원리 - 고급편_로그 추적기(V2 파라미터로 동기화 개발)

로그 추적기 V2 - 파라미터로 동기화 개발

• 트랜잭션 ID와 메서드 호출의 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 ID와 level을 다음 로그에 넘겨주는 것이다.
• 현재 로그 상태 정보인 ID와 level은 TraceId에 있다.
  • 따라서 TraceId를 다음 로그로 넘기면 된다.

HelloTraceV2

@Slf4j
@Component
public class HelloTraceV2 {
    private static final String START_PREFIX = "--->";
    private static final String COMPLETE_PREFIX = "<---";
    private static final String EX_PREFIX = "<X-";

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

    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
        TraceId nextId = beforeTraceId.createNextId();
        long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
        return new TraceStatus(nextId, 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());
        }
    }

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

• Request를 받는 첫 요청에는 begin()을 사용하고 이후 요청부터 beginSync()를 사용하면 된다.

테스트 코드

public class HelloTraceV2Test {

    @Test
    void begin_enc() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

로그

[29cbc39a] hello1
[29cbc39a] |--->hello2
[29cbc39a] |<---hello2 time=0ms
[29cbc39a] hello1 time=1ms

[1547c884] hello1
[1547c884] |--->hello2
[1547c884] |<X-hello2 time=1ms ex=java.lang.IllegalStateException
[1547c884] hello1 time=8ms ex=java.lang.IllegalStateException

요구사항

완성된 요구사항은 아래와 같다.

• 모든 Public 메서드의 호출과 응답을 로그로 출력
• 애플리케이션의 흐름을 방해햐면 안됨
  • 로그를 남긴다고 해서 비즈니스 로직 동작에 영향을 주면 안된다.
• 기능
  • 메서드 호출에 걸린 시간
  • 정상 흐름과 예외 흐름 구분
    • 예외 발생 시 예외 정보가 남아야 함
  • 메서드 호출의 깊이 표현
  • HTTP 요청을 구분
    • HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분 가능해야 함
    • 트랜잭션 ID (DB 트랜잭션이 아님)를 통해 구분한다.
      • HTTP 요청이 시작해서 끝날 때 까지 하나의 트랜잭션

 

출처: 김영한 지식공유자의 스프링 핵심 원리 고급편