Ch01. 예제 만들기 - 로그 추적기(2)

프로토타입 개발

TraceId.class

@Getter
public class TraceId {

    private String id;
    private int level;

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

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

    private String createId() {
        //앞 8자리만 사용 //중복이 될수 있지만 트랜잭션 ID 이기 때문에 상관 X
        return UUID.randomUUID().toString().substring(0, 8);
    }

    private TraceId createNextId(){
        return new TraceId(id, level + 1);
    }

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

    public boolean isFirstLevel(){
        return level == 0;
    }
}

• 트랜잭션 ID와 깊이를 표현하는 클래스
• createId() : UUID를 통해 TraceId를 생성한다( UUID는 너무 길기 때문에 8글자만 잘라서 사용한다)
• createNextId() : 트랜잭션 ID는 같고, level은 하나 증가된 TraceId를 반환한다
• createPreviousId() : 트랜잭션 ID는 같고, level은 하나 감소된 TraceId를 반환한다
• isFirstLevel() : 첫 번째 level(level == 0) 임을 확인하는 메서드

TraceStatus.class

TraceStatus

• 로그의 상태 정보를 나타낸다.
• traceId : 내부에 트랜잭션 ID와 level을 가지고 있다.
• startTimeMs : 로그 시작 시간이다. 로그 종료 시 이 시작 시간을 기준으로 시작~종료까지 전체 수행 시간을 구할 수 있다.
• message : 시작시 사용한 메시지이다. 이후 로그 종료 시에도 이 메시지를 사용해서 출력한다.

HelloTraceV1

@Slf4j
@Component
public class HelloTraceV1 {

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

• 실제 로그를 시작하고 종료할 수 있다. 그리고 로그를 출력하고 실행시간도 측정할 수 있다.
• begin() 
  • 로그를 시작한다.
  • 로그 메시지를 파라미터로 받아서 시작 로그를 출력한다.
  • 응답 결과로 현재 로그의 상태인 TraceStatus를 반환한다.
• end()
  • 로그를 정상 종료한다.
  • 파라미터로 시작 로그의 상태( TraceStatus )를 전달받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료 시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
  • 정상 흐름에서 호출한다.
• exception()
  • 로그를 예외 상황으로 종료한다.
  • TraceStatus , Exception 정보를 함께 전달받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.
  • 예외가 발생했을 때 호출한다.
• complete()
  • end() , exception() , 의 요청 흐름을 한 곳에서 편리하게 처리한다. 실행 시간을 측정하고 로그를 남긴다
• addSpace()
  • level에 따라 prefix를 깊이에 맞게 출력한다.
  • prefix: -->
    • level 0:
    • level 1: |-->
    • level 2: |    |-->
  • prefix: <--
    • level 0:
    • level 1: |<--
    • level 2: |     |<--
  • prefix: <x-
    • level 0:
    • level 1: |<x-
    • level 2: |     |<x-

Test

class HelloTraceV1Test {

    @Test
    public void beginEnd(){
        HelloTraceV1 trace = new HelloTraceV1();
        TraceStatus status = trace.begin("hello");
        trace.end(status);
    }


    @Test
    public void beginException(){
        HelloTraceV1 trace = new HelloTraceV1();
        TraceStatus status = trace.begin("hello");
        trace.exception(status, new IllegalStateException());
    }
}

• 참고: 이것은 온전한 테스트 코드가 아니다. 일반적으로 테스트라고 하면 자동으로 검증하는 과정이 필요하다. 이 테스트는 검증하는 과정이 없고 결과를 콘솔로 직접 확인해야 한다. 이렇게 응답 값이 없는 경우를 자동으로 검증하려면 여러 가지 테스트 기법이 필요하다. 이번 강의에서는 예제를 최대한 단순화하기 위해 검증 테스트를 생략했다.

적용

Controller

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;

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

Service

@Service
@RequiredArgsConstructor
public class OrderServiceV1 {

    private final OrderRepositoryV1 orderRepository;
    private final HelloTraceV1 trace;

    public void orderItem(String itemId){
        TraceStatus status = null;
        try{
            status = trace.begin("OrderController.request()");
            orderRepository.save(itemId);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
            throw e; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

Repository

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV1 {

    private final HelloTraceV1 trace;

    public void save(String itemId){
        TraceStatus status = null;
        try{
            status = trace.begin("OrderController.request()");
            //저장 로직
            if(itemId.equals("ex")){ //예외 발생
                throw new IllegalStateException("예외 발생");
            }
            sleep(1000);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
            throw e; //예외를 꼭 다시 던져주어야 한다.
        }
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• HelloTraceV1 trace : HelloTraceV1을 주입받는다. 참고로 HelloTraceV1 은 @Component 애노테이션을 가지고 있기 때문에 컴포넌트 스캔의 대상이 된다. 따라서 자동으로 스프링 빈으로 등록된다
• trace.begin(메서드명) : 로그를 시작할 때 메시지 이름으로 컨트롤러 이름 + 메서드 이름을 주었다. 이렇게 하면 어떤 컨트롤러와 메서드가 호출되었는지 로그로 편리하게 확인할 수 있다. (수작업)
• trace.exception()으로 예외까지 처리해야 하므로 지저분한 try , catch 코드가 추가된다
• begin()의 결과 값으로 받은 TraceStatus status 값을 end() , exception()에 넘겨야 한다. 결국 try , catch 블록 모두에 이 값을 넘겨야 한다
  • 따라서 try 상위에 TraceStatus status 코드를 선언해야 한다.
  • 만약 try 안에서 TraceStatus status를 선언하면 try 블록 안에서만 해당 변수가 유효하기 때문에 catch 블록에 넘길 수 없다. 따라서 컴파일 오류가 발생한다.
• throw e : 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 로그는 애플리케이션에 흐름에 영향을 주면 안 된다. 로그 때문에 예외가 사라지면 안된다

전체 흐름

• HelloTraceV1 덕분에 직접 로그를 하나하나 남기는 것보다는 편하게 여러 가지 로그를 남길 수 있었다.
• 하지만 로그를 남기기 위한 코드가 생각보다 너무 복잡하다.
• 문제점
  • 내 트랜잭션 ID, Level이 다음으로 전달되어야 한다.
  • 로그에 대한 문맥(Context)이 필요하다.