[고급편] 로그추적기 V2 (파라미터로 동기화)

로그 추적기 v2 개발

• v1의 문제점을 해결해보자.
  • 요청을 한 번만 했으니 트랜잭션 ID가 동일해야 하는데 깊이가 변경될 때마다 새로운 트랜잭션 ID가 발급된다.
  • 깊이가 다른데도 같은 깊이처럼 출력된다.
• 상태가 연동되지 못 하는 것은 당연히 이전 로그의 상태가 어떻게 되었는지 알 수 없기 때문이다.
• 가장 단순하게 처리하기 위해 로그의 상태 정보를 다음 로그에게 넘기는 방식으로 수정하면 된다.
  • 로그의 상태 정보인 트랜잭션 ID와 깊이값은 TraceId 클래스에 포함되어 있다.
  • 즉, TraceId를 다음 로그에 넘기면 된다.
• 파라미터 동기화 작업을 위해 기존의 TraceV1을 복사하여 TraceV2를 추가하자.
• 기존 TraceV1에서 메소드 하나만 추가되었다.

/**
    * 이전 로그의 상태와 동기화한다.
    * - 트랜잭션 ID는 기존과 동일하다.
    * - 깊이값은 하나 증가한다.
    * @param beforeTraceId 이전 로그의 상태
    * @param 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);
}

로그 추적기 v2 테스트

• TraceV2에서 단축키 Ctrl + Shift + T를 실행해서 테스트를 생성하자.

package com.example.trace;

import org.junit.jupiter.api.Test;

class TraceV2Test {
    @Test
    void begin_end_level2() {
        TraceV2 trace = new TraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        TraceV2 trace = new TraceV2();
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

• begin_end_level2 실행 로그

  [cd110c7e] hello1
  [cd110c7e] |–>hello2
  [cd110c7e] |<–hello2 time=2m
  [cd110c7e] hello1 time=11ms

• begin_exception_level2 실행 로그

  [040996e7] hello
  [040996e7] |–>hello2
  [040996e7] |<X-hello2 time=2ms ex=java.lang.IllegalStateException
  [040996e7] hello time=9ms ex=java.lang.IllegalStateException

로그 추적기 v2 적용

• 차이점을 확인하기 위해 기존의 v1 패키지를 복사해서 v2으로 추가하자.
  • v2 패키지 내부의 클래스명에서 v1을 v2로 변경한다.
  • 각 클래스의 내부 로직에서 참고하는 타 클래스도 v2인지 확인한다.
  • 컨트롤러에서 매핑 정보를 /v1/request에서 /v2/request로 변경한다.
• TraceV2를 적용해보자.

로그추적기 v2 적용 결과

성공하는 케이스

• 실행 후 http://localhost:8081/v2/request?itemId=test로 이동해서 확인해보자.

[b7f4ae5d] OrderController.request()
[b7f4ae5d] |–>OrderService.orderItem()
[b7f4ae5d] | |–>OrderRepository.save()
[b7f4ae5d] | |<–OrderRepository.save() time=1008ms
[b7f4ae5d] |<–OrderService.orderItem() time=1008ms
[b7f4ae5d] OrderController.request() time=1009ms

실패하는 케이스

• 실행 후 http://localhost:8081/v2/request?itemId=ex로 이동해서 확인해보자.

[0a546b1c] OrderController.request()
[0a546b1c] |–>OrderService.orderItem()
[0a546b1c] | |–>OrderRepository.save()
[0a546b1c] | |<X-OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
[0a546b1c] |<X-OrderService.orderItem() time=2ms ex=java.lang.IllegalStateException: 예외 발생!
[0a546b1c] OrderController.request() time=2ms ex=java.lang.IllegalStateException: 예외 발생!

로그추적기 v2 적용 결과 분석

• 트랜잭션(HTTP 요청)을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다.
• TraceId 의 동기화를 위해서는 관련 메서드의 모든 파라미터를 수정해야 한다.
  • 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이 발생할 수 있다.
• 로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다.
  • 서비스를 무조건 컨트롤러에서 호출한다는 보장이 없다.
    • 예시 : 스케졸러

출처

• 스프링-핵심-원리-고급편