Spring Core - 로그 추적기(V2 파라미터로 동기화 개발)

V2 파라미터로 동기화 개발

트랜잭션ID와 메서드 호출의 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션ID와 level을 다음 로그에 넘겨주면 된다.

현재 로그의 상태 정보인 트랜잭션ID와 level은 TraceId에 포함되어 있다. 따라서 TraceId를 다음 로그로 넘겨주면 된다. 이기능을 추가한 HelloTraceV2를 개발해보자.

 

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

        //1.로그 출력
        //begin에서 TraceId를 담은 TraceStatus가 생성된 다음
        //끝날대 하나의 트랜잭션의 결과에 따라
        // end메서드 혹은 exception 메서드로 반환된다.
        return new TraceStatus(traceId, startTimeMs, message);

    }

    //V2추가
    public TraceStatus beginSync(TraceId beforeTraceId,String message){
        TraceId traceId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}",traceId.getId(),addSpace(START_PREFIX,traceId.getLevel()),
        message);
        
        return new TraceStatus(traceId, startTimeMs, message);

    }

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

        //1.로그 출력
        //begin에서 TraceId를 담은 TraceStatus가 생성된 다음
        //끝날대 하나의 트랜잭션의 결과에 따라
        // end메서드 혹은 exception 메서드로 반환된다.
        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());
        }

    }

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

 

HelloTraceV2는 기존 코드인 HelloTraceV2와 같고, beginSync(..)가 추가 되었다.

//V2추가
    public TraceStatus beginSync(TraceId beforeTraceId,String message){
        TraceId traceId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}",traceId.getId(),addSpace(START_PREFIX,traceId.getLevel()),message);

        return new TraceStatus(traceId, startTimeMs, message);
    }

 

beginSync(..)

• 기존 TraceId에서 createNextId()를 통해 다음 ID를 구현한다.
• createNextId()의 TraceId 생성 로직은 다음과 같다.
  • 트랜잭션ID는기존과 같이 유지한다.
  • 깊이를 표현하는 Level은 하나 증가한다.(0 → 1)

 

테스트 코드를 통해 잘 동작하는지 확인해보자.

 

HelloTraceV2Test

class HelloTraceV2Test {

    @Test
    void begin_end(){
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello");
        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("hello");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(),"hello2");
        trace.exception(status2,new IllegalStateException());
        trace.exception(status1 ,new IllegalStateException());
    }

}

 

처음에는 begin(...)을 사용하고, 이후에는 beginSync(..)를 사용하면 된다. beginSync()를 호출할 때 직전 로그의 traceId 정보를 넘겨주어야 한다.

 

실행 로그를 보면 같은 트랜잭션ID를 유지하고 level을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다. 

 

---

로그 추적기 V2 - 적용

메서드 호출의 깊이를 표현하고, HTTP 요청도 구분해보자.

이렇게 하려면 처음 로그를 남기는 OrderContorller.createOrder()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 다음 차례인 OrderService.orderItem()에서 로그를 남기는 시점에 알아야한다.

결국 현재 로그의 상태 정보인 트랜잭션ID와 level이 다음으로 전달되어야 한다.

이 정보는 TraceStatus.traceId에 담겨있다. 따라서 traceId를 컨트롤러에서 서비스를 호출할 때 넘겨주면 된다. 

 

traceId를 넘기도록 V2 전체 코드를 수정하자

 

OrderControllerV2

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {
    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

    @GetMapping("/v2/order")
    public String createOrder(String itemId){
        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.createOrder()");
            orderService.orderItem(status.getTraceId(),itemId);
            trace.end(status);
            return "ok";
        }catch (Exception e){
            trace.exception(status,e);
            throw e; //예외를 꼭 다시 던저주어야 한다.
        }

    }

}

• TraceStatus status = trace.begin() 에서 반환 받은 TraceStatus에는 트랜잭션ID와 level 정보가 있는 TraceId가 있다.
• orderService.orderItem()을 호출할 때 TraceId를 파라미터로 전달한다.
• TraceId를 파라미터로 전달하기 위해 OrderServiceV2.orderItem()의 파라미터에 TraceId를 추가해야 한다.

 

OrderServiceV2

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(TraceId traceId, String itemId){

        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId,"OrderService.orderItem()");
            orderRepository.save(status.getTraceId(),itemId);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status,e);
            throw e;
        }
    }
}

 

• orderItem()은 파라미터로 전달 받은 traceId를 사용해서 trace.beginSync()를 실행한다.
• beginSync()는 내부에에서 다음 traceId 인스턴스를 생성하면서 트랜잭션ID는 유지하고 level은 하나 증가시킨다.
• beginSync()가 반환한 새로운 TraceStatus를 orderRepository.save()를 호출하면서 파라미터로 전달한다.
• TraceId()를 파라미터로 전달하기 위해 orderReposioty.save()의 파라미터에 TraceId를 추가해야 한다.

 

실행 로그를 보면 같은 HTTP 요청에 대해서 트랜잭션ID가 유지되고, level도 잘 표현되는 것을 확인할 수 있다.

 

남은 문제

• HTTP 요청을 구분하고 깊이 표현하기 위해서 TraceId 동기화가 필요하다.
• TraceId의 동기화를 위헤서 관련 메서드의 모든 파라미터를 수정해야 한다.
  • 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
• 로그를 처음 시작할 때는 begin()을 호출하고, 처음이 아닐때는 beginSync()를 호출해야 한다.
  • 만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라. 다른곳에서 서비스부터 호출하는 상황이라면 파라미터로 넘길 TraceId가 없다.

 

HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId를 파라미터로 넘기는 것 말고 다른 대안은 없는 걸까?

 

[출처 - 스프링 핵심원리-고급편, 저 김영한]

https://www.inflearn.com/course/%EC%8A%A4%ED%94%84%EB%A7%81-%ED%95%B5%EC%8B%AC-%EC%9B%90%EB%A6%AC-%EA%B3%A0%EA%B8%89%ED%8E%B8

스프링 핵심 원리 - 고급편 강의 - 인프런