[스프링 핵심 원리 - 고급편] #2 예제 만들기 (2)

[newh08]

로그 추적기 V1 - 적용

v0 를 복사해 v1 만들기
여기에 helloTraceV1 을 적용해보자.

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;

    @GetMapping("/v1/request")
    public String request(String itemId) {
        TraceStatus status = trace.begin("OrderController.request()");

        orderService.orderItem(itemId);
        trace.end(status);
        return "ok";
    }

컨트롤러에 이렇게 적용하고 실행하면

정상 상황에선 이렇게 trace가 남지만

예외 발생시 이렇게 로그가 남게됨.
코드를 보면 중간에 예외가 터져버려 나가게되고 end 호출이 안됨
그래서 try catch 로 예외를 잡아줘야한다.

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

이렇게 변경하는데, 예외를 다시 안던지면 정상 흐름이 되서 예외를 꼭 던져줘야함.

• 단순하게 trace.begin(), trace.end() 코드만 추가하면 될줄 알았는데 예외 처리를 위한 try catch 가 추가 필요
• begin() 의 결과였던 status 를 exception() 에 넘겨야해서 이를 상위에서 선언해줘야함.
• catch 에서 예외를 꼭 다시 던져줘야한다.

다음으로 OrderService 에 적용

@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("OrderService.request()");
            orderRepository.save(itemId);
            trace.end(status);
        } catch(Exception e)
        {
            trace.exception(status, e);
            throw e; // 예외를 꼭 던져줘야함.
        }
    }
}

그리고 리포지토리에도 적용

public class OrderRepositoryV1 {

    private final HelloTraceV1 trace;
    
    // 저장 로직
    public void save(String itemId)  {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepository.save()");
            if (itemId.equals("ex")) {
                throw new IllegalStateException("예외 발생");
            }
            sleep(1000);
            trace.end(status);
        } catch(Exception e)
        {
            trace.exception(status, e);
            throw e; // 예외를 꼭 던져줘야함.
        }
    }

정상 로그
public class OrderRepositoryV1 {

private final HelloTraceV1 trace;

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

예외 로그

이를 그림으로 보면

참고: 아직 level 관련 기능을 개발하지 않았다. 따라서 level 값은 항상 0이다. 그리고 트랜잭션ID 값도 다르다. 이 부분은 아직 개발하지 않았다.
HelloTraceV1 덕분에 직접 로그를 하나하나 남기는 것 보다는 편하게 여러가지 로그를 남길 수 있었다. 하지만 로그를 남기기 위한 코드가 생각보다 너무 복잡하다. 지금은 우선 요구사항과 동작하는 것에만 집중하자.

요구사항**

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

남은 기능을 구현하려면 직전 로그의 깊이와 트랜잭션 ID 가 무엇인지 알아야 할 수 있음.

예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem() 에서 로그를 남길 때 알아야한다.
결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다.
정리하면 로그에 대한 문맥(Context ) 정보가 필요하다.

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

트랜잭션ID 와 메서드 호출깊이를 표현하는 가장 단순한 방법은, 첫 로그에서 사용한 트랜잭션ID 와 level 을 다음 로그에 넘겨주는 것이다.
현재 로그의 상태정보 (트랜잭션ID, level) 은 TraceId 에 포함되어 있음. 따라서 이를 다음 로그에 넘겨주면 된다.
이를 포함한 HelloTraceV2 를 만들어보자.

    // V2 에서 추가
    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);
    }

이 코드를 HelloTraceV2 에 추가

이렇게 하면
TraceId 는 유지되면서 레벨이 증가하는 로그가 찍힘.

테스트를 먼저 해보자

class HelloTraceV2Test {

    @Test
    void begin_end() {
        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 IllegalArgumentException());
        trace.exception(status1, new IllegalArgumentException());
    }

로그 추척기 V2 - 적용

마찬자기로 복붙으로 v2 만들자.
메서드 깊이와 HTTP 요청을 구분하려면 처음 로그를 남기는 OrderController.request() 에서 어떤 깊이와 어떤 트랜잭션 ID 를 사용했는지 다음차례인 OrderService.orderItem() 에서 알아야 한다.
이는 traceId 에 담겨있고 이를 컨트롤러에서 서비스를 호출할때 넘겨줘야한다.

public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

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

이렇게 컨트롤러에서 서비스를 호출할때 traceId 를 넘겨주고

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.request()");
            orderRepository.save(traceId, itemId);
            trace.end(status);
        } catch(Exception e)
        {
            trace.exception(status, e);
            throw e; // 예외를 꼭 던져줘야함.
        }
    }

서비스 에서도 traceId 를 받도록 메서드를 수정한 다음
trace.beginSync 를 사용

리포지토리도 마찬가지로 적용!

v2 를 실행해보면
정상상황 및 에러상황