Spring Core - 로그 추적기(프로토타입, V1)

로그 추적기

요구사항

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

 

프로토타입 개발

 

애플리케이션의 모든 로직에 직접 로그를 남겨도 되지만, 그것보다는 더 효율적인 개발 방법이 필요하다. 특히 트랜잭션ID와 깊이를 표현하는 방법은 기존 정보를 이어 받아야하기 때문에 단순히 로그만 남긴다고 해결할 수 있는 것은 아니다.

 

요구사항에 맞추어 애플리케이션에 효과적으로 로그를 남기기 위한 추적기 개발을 해보자.

 

먼저 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId, TraceStatus 클래스를 만들어보자

 

TraceId 클래스

package com.spring.core.trace;

import java.util.UUID;

public class TraceId {

    private String id;
    
    //log 출력시 공백의 값
    private  int level;

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

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

    private String creatId() {
        //앞 8자리만 사용
        return UUID.randomUUID().toString().substring(0,8);
    }

    //Controller -> Service 레이어 간의
    //depth 를 공백을 사용 직관적으로 표현 한다.
    public TraceId createNextId(){
        return  new TraceId(id,level + 1);
    }

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

    public boolean isFirstLevel(){
        //first 레벨인지 아닌지
        return level == 0;
    }

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

 

로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다.

여기서는 트랜잭션ID와 깊이를 표현하는 level을 묵어서 TraceId 라는 개념을 만들었다.

TraceId는 단순히 id(트랜잭션ID)와 level 정보를 함께 가지고 있다.

 

UUID

TraceId를 처음 생성하면 createId()를 사용해서 UUID를 만들어 낸다. UUID가 너무 길기 때문에 여기서는 앞 8자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다. 여기서는 만들어진 값을 트랜잭션ID로 사용한다.

 

createNextId()

같은 트랜잭션ID를 가지고 있지만 depth가 깊은 다음 TraceId 객체를 생성한다. 

 

createPreviousId()

createNextId()의 반대 역할을 한다. id는 이전과 같은 트랜잭션ID를 같지만, level은 하나 감소한다.

 

isFirstLevel()

첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드 

---

TraceStatus 클래스

package com.spring.core.trace;

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 TraceId getTraceId() {
        return traceId;
    }

    public Long getStartTimeMs() {
        return startTimeMs;
    }

    public String getMessage() {
        return message;
    }
}

 

로그의 상태 정보를 나타낸다.

 

로그를 시작하면 끝이 있어야 한다.

[77e~] OrderController.createOrder()    //로그 시작
[77e~] OrderController.createOrder()  time=10000ms    //로그 종료

TraceStatus 는 로그를 시작할 때의 상태 정보를 가지고 있다. 해당 상태 정보를 로그 종료할 때 사용한다.

 

• traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
• startTimeMs : 로그 시작시간이다. 로그 종료시 로그 (종료시간 - 시작시간)을 계산하면 전체 수행 시간을 구할 수 있다.
• message : 시작시 사용한 메시지(사용 메서드 이름)이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.

---

HelloTraceV1

@Slf4j
@Component
public class helloTraceV1 {
}

 

싱글톤으로 스프린 컨테이너에 등록해서 사용할 것이기 때문에 @Component 애노테이션을 사용한다. 

---

로그 추적기 V1 - 적용

v1적용하기

OrderControllerV1, OrderService1, OrderRepository1에 추적기를 적용해 보자

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {
    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;

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

    }

}

 

• trace.begin("Ordercontroller.createOrder()") : 로그를 시작할 때 메시지 이름으로 컨트롤러 이름 + 메서드 이름을 주었다. 이렇게 하면 어떤 컨트롤러와 메서드가 호출되었는지 로그로 편리하게 확인할 수 있다. 물론 수작업이다.
• 단순하게 trace.begin(), trace.end() 코드가 두 줄만 적용하면 될 줄 알았지만, 실상은 그렇지 않다. trace.exception()으로 예외까지 처리해야 하므로 지저분한 try, catch 코드가 추가된다.
• begin()의 결과 값으로 받은 TraceStatus status 값을 end(), exception()에 넘겨야 한다. 결국 try와 catch 블록 모두에 status 값을 넘겨야 하므로 try 상위에 TraceStatus status코드를 선언해야 한다.
• throw e : 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 trace.exception(status,e)가 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 애플리케이션 흐름에 영향을 주면 안된다. 로그 때문에 예외가 사라지면 안되기 때문이다. 

 

남은 문제

요구사항

• 메서드 호출의 깊이 표현
• HTTP 요청을 구분
  • HTTP요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야한다.
  • 트랜잭션ID(DB 트랜잭션 X)

아직 구현하지 못한 요구사항은 메서드 호출의 깊이를 표현하고, 같은 HTTP 요청이면 같은 트랜잭션 ID를 남기는 것이다. 예를 들어서 OrderController.createOrder()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 그 다음에 로그를 남기는 OrderService.orderItem()에서 로그를 남길 때 알아야한다. 결국 현재 로그의 상태 정보인 트랜잭션ID와 level이 다음으로 전달되어야 한다.  정리하면 로그에 대한 문맥(Context)정보가 필요하다.

 

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

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

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