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

[YuDeokRin]

섹션2. 예제 만들기

1️⃣ 프로젝트 생성

• 프로젝트 생성 정보

  • Project : Gradle - Groovy

  • Language : Java

  • Spring Boot : 3.4.3

  • Project Metadata

    • Group : hello
    • Artifact : advanced
    • Name : advanced
    • Packaging : Jar
    • Java : 17

  • Dependencies

    • Spring Web
    • Lombok

2️⃣ 예제 프로젝트 만들기 - V0

• 만들면서 학습 해볼 애플리케이션은 Controller → Service → Repository 순으로 만들어보자.

• ✅ OrderRepositoryV0

package hello.advanced.app.V0;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository //컴포넌 스캔의 대상이 되어, 스프링 빈으로 자동 등록된다.
@RequiredArgsConstructor
public class OrderRepositoryV0 {

    public void save(String itemId) {
        //저장 로직
        if (itemId.equals("ex")) { // itemId가 ex로 넘어오면 문제 발생(예외 발생) 
            throw new IllegalAccessException("예외 발생!");
        }
        
        sleep(1000); // 리포지토리는 상품을 저장하는데 약 1초 정도 걸리는 것으로 1초를 지연 줌
    }
    
    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• ✅ OrderServiceV0

package hello.advanced.app.V0;

import lombok.RequiredArgsConstructor;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;

@Service
//@RequiredArgsConstructor
public class OrderService {
    
    
    private final OrderRepositoryV0 orderRepository;

    @Autowired
    public OrderService(OrderRepositoryV0 orderRepository) {
        this.orderRepository = orderRepository;
    }

    public void orderItem(String itemId) {
        orderRepository.save(itemId);
    }
}

• ✅ OrderControllerV0

package hello.advanced.app.V0;

import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController // @Controller + @ResponseBody
@RequiredArgsConstructor
public class OrderControllerV0 {
    
    private final OrderServiceV0 orderService;

    @GetMapping
    public String request(String itemId) {
        orderService.orderItem(itemId);
        return "ok";
    }
        
}

• 결과 - 정상적인 결과

• 결과 - ex 파라미터 요청 시

• 결과 예외 로그

• 실무에서 일반적으로 사용하는 흐름
  • 컨트롤러 → 서비스 → 리포지토리

3️⃣ 로그 추적기 - 요구사항 분석

➡️ 상황

• 애플리케이션이 병목현상이 자주 일어나는 상황
• 로그 추적기 기능 만들기

✅요구사항

• 모든 public 메서드의 호출과 응답 정보를 로그로 출력

• 애플리케이션의 흐름을 변경하면 안됨

  • 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨

• 메서드 호출에 걸린 시간

• 정상 흐름과 예외 흐름 구분

  • 예외 발생시 예외 정보가 남아야 함

• 메서드 호출의 깊이 표현

• HTTP 요청을 구분

  • HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
  • 트랜잭션 ID (DB 트랜잭션 X), 여기서는 하나의 HTTP 요청이 시작해서 끝이 날 때 까지를 하나의 트랜잭션이라고 함

• 정상 요청

정상 요청
 [796bccd9] OrderController.request()
 [796bccd9] |-->OrderService.orderItem()
 [796bccd9] |   |-->OrderRepository.save()
 [796bccd9] |   |<--OrderRepository.save() time=1004ms
 [796bccd9] |<--OrderService.orderItem() time=1014ms
 [796bccd9] OrderController.request() time=1016ms

• OrderRepository.save() time=1004ms : 응답 시간 1초 정도

• 예외 발생

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

참고
모니터링 툴을 도입하면 많은 부분이 해결된다. 하지만 모니터링 툴로도 못잡는 것이 있을 수 있다.

4️⃣ 로그 추적기 V1 - 프로토타입 개발

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

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

• TraceId

package hello.advanced.trace;

import java.util.UUID;

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() {
        return UUID.randomUUID().toString().substring(0, 8); // 앞자리 8자리만 사용
    }
    
    
    public TraceId createNextId() {
        return new TraceId(id, level + 1);
    }

    public TraceId createPreviousId() {
        return new TraceId(id, level - 1);
    }
    
    
    // 첫번째 레벨인지 확인하는 메서드 
    public boolean isFirstLevel() {
        return level == 0;
    }

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

• 위 코드 설명
  • 로그 추적기는 트랜잭션ID와 깊이를 표한하는 방법이 필요
  • 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId라는 개념 생성
  • TraceId는 단순히 id, level 정보를 함께 가지고 있음

[796bccd9] OrderController.request() //트랜잭션ID:796bccd9, level:0
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID:796bccd9, level:1
[796bccd9] | |-->OrderRepository.save()//트랜잭션ID:796bccd9, level:2

• UUID
  • createId에서 UUID 개념을 사용하는데 여기서는 UUID가 너무 길어서 앞에 8자리만 사용하겠다.
  • 여기서는 UUID 값을 트랜잭션ID로 사용

ab99e16f-3cde-4d24-8241-256108c203a2 //생성된 UUID
ab99e16f //앞 8자리만 사용

• createNextId

  • 다음 TraceId를 만든다
  • 깊이가 증가해도 트랜잭션 ID는 같음
  • 깊이가 + 1

• createPreviousId

  • createNextId()의 반대 역할

• TraceStatus

package hello.advanced.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;
    }
}

• 로그를 시작하면 끝이 있어야 함.

[796bccd9] OrderController.request() //로그 시작
[796bccd9] OrderController.request() time=1016ms //로그 종료

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

• TraceId : 내부에 트랜잭션 ID와 level을 가지고 있다.

• startTimeMs : 로그 시작시간이다. 로그 종료시 이 시작 시간을 기준으로 시작~종료까지 전체 수행 시간을 구할 수 있다.

• message : 시작시 사용한 메시지이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.

• HelloTraceV1

package hello.advanced.trace;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

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

    //level = 0
    //level = 1 | -->
    //level = 2 |    |-->
    
    //level = 2 ex |    |<X-
    //level = 1 ex |<X-
    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()
    • end()
      • 로그를 정상 종료한다.
      • 파라미터로 시작 로그의 상태(TraceStatus)를 전달 받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
    • exception()
      • 로그를 예외 상황으로 종료한다.
      • TraceStatus, Exception 정보를 함께 전달 받아서 실행 시간, 예외 정보를 포함한 결과 로그를 출력한다.

  • 비공개 메서드

    • complete()
    • prefix: -->
      • level 0: ``
      • level 1: |-->
      • level 2: | |-->
    • prefix: <--
      • level 0: ``
      • level 1: |<--
      • level 2: | |<--
    • prefix: <X-
      • level 0: ``
      • level 1: |<X-
      • level 2: | |<X-

📝테스트 코드 작성

• HelloTraceV1Test

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

class HelloTraceV1Test {

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

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

• begin_end 결과

22:35:23.483 [Test worker] INFO hello.advanced.trace.HelloTraceV1 -- [4daf2577] hello
22:35:23.483 [Test worker] INFO hello.advanced.trace.HelloTraceV1 -- [4daf2577] hello time=0ms

• begin_exception 결과

22:35:23.475 [Test worker] INFO hello.advanced.trace.HelloTraceV1 -- [dd10b67f] hello
22:35:23.478 [Test worker] INFO hello.advanced.trace.HelloTraceV1 -- [dd10b67f] hello time=3ms ex=java.lang.IllegalStateException

주의!

• 지금까지 만든 로그 추적기가 어떻게 동작하는지 제대로 알고 있어야한다.그래야지 다음 단계로 갈 수 있음

5️⃣ 로그 추적기 V1 - 적용

• OrderControllerV1

package hello.advanced.app.V1;

import hello.advanced.app.V0.OrderServiceV0;
import hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController // @Controller + @ResponseBody
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;

    @GetMapping("/v1/request")
    public String request(String itemId) {

        TraceStatus status = null;

        try { // try-catch 하는 이유 : 예외가 터지는 경우에도 로그를 출력해주어야하기 때문이다.
            status = trace.begin("OrderController.request()");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 에외를 꼭 다시 던져주어야 한다.
        }

    }
}

• OrderServiceV1

package hello.advanced.app.V1;

import hello.advanced.app.V0.OrderRepositoryV0;
import hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.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("OrderService.orderItem()");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }

    }

}

• OrderRepositoryV1

package hello.advanced.app.V1;

import hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
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")) { // itemId가 ex로 넘어오면 문제 발생
                throw new IllegalStateException("예외 발생!");
            }

            sleep(1000);
            trace.end(status);
        } catch (IllegalStateException e) {
            trace.exception(status, e);
            throw e;
        }
    }

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

• 정상로그 실행

2025-03-03T19:58:04.368+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [b20904de] OrderController.request()
2025-03-03T19:58:04.369+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [d3d65403] OrderService.orderItem()
2025-03-03T19:58:04.370+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [6b5b58ad] OrderRepository.save()
2025-03-03T19:58:05.375+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [6b5b58ad] OrderRepository.save() time=1005ms
2025-03-03T19:58:05.376+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [d3d65403] OrderService.orderItem() time=1007ms
2025-03-03T19:58:05.377+09:00  INFO 48345 --- [advanced] [io-8080-exec-10] hello.advanced.trace.HelloTraceV1        : [b20904de] OrderController.request() time=1009ms

• 예외 실행 로그

2025-03-03T19:58:50.575+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [8caef9ca] OrderController.request()
2025-03-03T19:58:50.576+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [97443b35] OrderService.orderItem()
2025-03-03T19:58:50.576+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [b526e11e] OrderRepository.save()
2025-03-03T19:58:50.576+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [b526e11e] OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T19:58:50.577+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [97443b35] OrderService.orderItem() time=1ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T19:58:50.577+09:00  INFO 48345 --- [advanced] [nio-8080-exec-3] hello.advanced.trace.HelloTraceV1        : [8caef9ca] OrderController.request() time=2ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T19:58:50.579+09:00 ERROR 48345 --- [advanced] [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.IllegalStateException: 예외 발생!] with root cause

java.lang.IllegalStateException: 예외 발생!

✅ 요구사항

• 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력

• 애플리케이션의 흐름을 변경하면 안됨

  • 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨

• 메서드 호출에 걸린 시간

• 정상 흐름과 예외 흐름 구분

  • 예외 발생시 예외 정보가 남아야 함

• 메서드 호출의 깊이 표현

• HTTP 요청을 구분

  • HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
  • 트랜잭션 ID (DB 트랜잭션X)

• 아직 구현 못한 것들은 위에 나와있듯이 메서드 호출의 깊이, HTTP 요청을 구분하는 일이다. 다음 장에서 구현을 해보자.

• 메서드 호출의 깊이가 왜알아야 할까?

  • OrderController.request()에서 로그를 남갈 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem()에서 로그로 남길 때 알아야한다.

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

• HelloTraceV2

package hello.advanced.trace;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@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);
        return new TraceStatus(traceId, startTimeMs, message);
    }
    
    //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);
    }

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

    //level = 0
    //level = 1 | -->
    //level = 2 |    |-->

    //level = 2 ex |    |<X-
    //level = 1 ex |<X-
    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();
    }

}

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

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

✅ 테스트 코드

• HelloTraceV2Test

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.HelloTraceV2;
import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

class HelloTraceV2Test {

    @Test
    void begin_end_level2() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status = trace.begin("hello");
        TraceStatus status2 = trace.beginSync(status.getTraceId(), "hello2");
        trace.end(status2);
        trace.end(status);
    }

    @Test
    void begin_exception_level2() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status = trace.begin("hello");
        TraceStatus status2 = trace.beginSync(status.getTraceId(), "hello2");

        trace.exception(status2, new IllegalStateException());
        trace.exception(status, new IllegalStateException());
    }
}

• beginSync()를 호출할 때 직전 로그의 traceId정보를 넘겨주어야한다.

• 출력 결과(로그) - begin_end_level2

19:26:18.690 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [bb07be54] hello
19:26:18.694 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [bb07be54] |--> hello2
19:26:18.694 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [bb07be54] |<--hello2 time=1ms
19:26:18.694 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [bb07be54] hello time=4ms

• 출력 결과(로그) - begin_exception_level2

19:26:42.803 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [6608f81e] hello
19:26:42.807 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [6608f81e] |--> hello2
19:26:42.807 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [6608f81e] |<X-hello2 time=2ms ex=java.lang.IllegalStateException
19:26:42.807 [Test worker] INFO hello.advanced.trace.HelloTraceV2 -- [6608f81e] hello time=4ms ex=java.lang.IllegalStateException

7️⃣ 로그 추적기 V2 - 적용

✅ V2 적용 하기

• 메서드 호출의 깊이 추가

• HTTP 요청 구분 추가

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

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

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

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

• OrderControllerV2

package hello.advanced.app.V2;

import hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.HelloTraceV2;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController // @Controller + @ResponseBody
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

    @GetMapping("/v2/request")
    public String request(String itemId) {

        TraceStatus status = null;

        try { // try-catch 하는 이유 : 예외가 터지는 경우에도 로그를 출력해주어야하기 때문에
            status = trace.begin("OrderController.request()");
            orderService.orderItem(status.getTraceId(), itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 에외를 꼭 다시 던져주어야 한다.
        }
    }
}

• OrderControllerV2 추가된 코드 및 설명

  • TraceStatus status = trace.begin()에서 반환 받는 TraceStatus에는 트랜잭션ID와 Level정보가 있는 TraceId가 있다.
  • orderService.orderItem(status.getTraceId(), itemId);에서 status.getTraceId() 추가 함
  • TraceId를 파라미터로 전달하기 위해 OrderServiceV2.orderItem()의 파라미터에 TraceId를 추가해야한다.

• OrderServiceV2

package hello.advanced.app.V2;

import hello.advanced.trace.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@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;
        }

    }

}

• OrderServiceV2 추가된 코드 및 설명

  • orderItem()은 파라미터로 전달 받은 tarceId를 사용해서 trace.beginSync()를 실행
  • trace.beginSync()는 내부에서 다음 traceId를 생성하면서 트랜잭션ID는 유지하고 level은 하나 증가시킨다.

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

  • trace.beginSync()가 반환한 새로운 TraceStatus를 orderRepository.save(status.getTraceId(), itemId);를 호출하면서 추가된 파라미터(traceId)와 함께 전달한다.

• OrderRepositoryV2

package hello.advanced.app.V2;

import hello.advanced.trace.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {

    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {

        TraceStatus status = null;

        try {
            status = trace.beginSync(traceId,"OrderRepository.save()");
            //저장 로직
            if (itemId.equals("ex")) { // itemId가 ex로 넘어오면 문제 발생
                throw new IllegalStateException("예외 발생!");
            }

            sleep(1000);
            trace.end(status);
        } catch (IllegalStateException e) {
            trace.exception(status, e);
            throw e;
        }
    }

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

• OrderRepositoryV2 추가된 코드 및 설명

  • save()는 파라미터로 전달 받은 traceId를 사용해서 trace.beginSync()를 실행한다.
  • beginSync()는 내부에서 다음 traceId를 생성하면서 트랜잭션ID는 유지하고 level은 증가시킨다.
  • beginSync()는 이렇게 갱신된 traceId로 새로운 TraceSatus를 반환한다.
  • trace.end(status)를 호출하면서 반환된 TraceStatus를 전달한다.

• 정상 로그 실행

2025-03-03T19:59:56.557+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] OrderController.request()
2025-03-03T19:59:56.558+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] |--> OrderService.orderItem()
2025-03-03T19:59:56.558+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] |   |--> OrderRepository.save()
2025-03-03T19:59:57.563+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] |   |<--OrderRepository.save() time=1005ms
2025-03-03T19:59:57.564+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] |<--OrderService.orderItem() time=1006ms
2025-03-03T19:59:57.565+09:00  INFO 48345 --- [advanced] [nio-8080-exec-6] hello.advanced.trace.HelloTraceV2        : [57488c09] OrderController.request() time=1008ms

• 예외 오류 실행

2025-03-03T20:00:47.414+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] OrderController.request()
2025-03-03T20:00:47.415+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] |--> OrderService.orderItem()
2025-03-03T20:00:47.415+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] |   |--> OrderRepository.save()
2025-03-03T20:00:47.416+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] |   |<X-OrderRepository.save() time=1ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T20:00:47.416+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] |<X-OrderService.orderItem() time=1ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T20:00:47.416+09:00  INFO 48345 --- [advanced] [nio-8080-exec-1] hello.advanced.trace.HelloTraceV2        : [65bd0883] OrderController.request() time=2ms ex=java.lang.IllegalStateException: 예외 발생!
2025-03-03T20:00:47.417+09:00 ERROR 48345 --- [advanced] [nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.IllegalStateException: 예외 발생!] with root cause

java.lang.IllegalStateException: 예외 발생!

✅ 요구사항

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

🚨남은 문제

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

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

[newh08]

고생하셨습니다!

[YuDeokRin]

오늘까지 섹션3을 다 ....해서 올리겠습니다