[인프런 김영한 스프링 핵심 원리 - 고급편] 예제 만들기

예제 프로젝트 - V0

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV0 {
    public void save(String itemId) {
        //저장 로직
        if (itemId.equals("ex")) {
            throw new IllegalStateException("예외 발생!");
        }
        sleep(1000);
    }

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

@Service
@RequiredArgsConstructor
public class OrderServiceV0 {
    private final OrderRepositoryV0 orderRepository;

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

@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {
    private final OrderServiceV0 orderService;

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

• 상품 주문 예제 코드
  
  • Repository
    • sleep(1000) - 상품 저장 시 1초의 시간이 소요될 것으로 가정함으로 지정
    • itemId 값이 ex로 넘어오면 예외를 발생 시킴

---

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

• 요구사항
  • 모든 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

예외 발생
[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: 예외 발생!

---

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

public class TraceId {
    private String id; //트랜잭션 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);
    }

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

• 로그 추적기를 위한 기반 데이터 클래스 예제
  • createId() : 랜덤한 UUID를 생성하고 생성된 UUID가 너무 길기에 앞 8자리만 잘라서 사용하는 기능
  • createNextId() : id는 같고 level이 증가하는 기능
  • createPreviousId() : id는 같고 level이 감소하는 기능
  • isFirstLevel() : 첫 번째 level 여부를 확인하는 기능

 

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

• 로그의 상태 정보 클래스 예제
  • 요구사항에 따라 로그를 시작할 때의 상태 정보를 가지고 있다가 종료할 때 사용된다.
  • message : 시작 시 사용한 메시지로 로그 종료 시에도 출력하기 위해 사용하는 필드

 

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

• 로그 출력을 위한 예제 클래스
  • @Component를 사용해서 싱글톤으로 스프링 빈을 등록하고 사용
  • begin() : 로그를 시작하고 메시지를 받아서 시작 로그를 출력하는 기능
    • 응답 결과로 로그 상태 TraceStatus 반환
  • end() : 정상 흐름에서 호출되는 메소드로 로그를 정상 종료하는 기능
    • 시작 로그 상태 TraceStatus를 받아서 실행 시간과 시작 메시지와 동일한 메시지 출력
  • exception() : 예외가 발생했을 때 호출되는 메소드로 로그를 예외 상황으로 종료하는 기능
    
    • 로그 상태 TraceStatus와 Exception 정보를 받아서 시간, 예외 정보 등 결과 로그를 출력
  • complete() : 실행 시간 측정하고 로그를 남길 수 있도록 요청 흐름을 한 곳에서 편리하게 처리하는 기능
  • addSpace() : 로그를 형식에 맞게 (level 수준에 따라 다르게) 출력하도록 하는 기능

---

로그 추적기 V1 - 적용

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

    @GetMapping("/v1/request")
    public String request(@RequestParam("itemId") 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
@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;
        }
    }
}

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

• 로그 추적기를 적용한 V1 예제
  • OrderController/Service/RepositoryV1
    • 로그 출력을 위해 스프링 빈으로 등록된 HelloTraceV1를 주입받는다.
    • 로그 메시지에 아직까지는 수작업으로 컨트롤러 이름, 메소드 이름을 넣어줬다.
    • 예외 처리를 위해 try-catch를 사용할 때 try, catch에서 모두 status 변수를 사용하기 위해서 try 이전에 status를 선언하고 null로 초기화 해줘야 한다.
    • throw e : 예외를 다시 던져주지 않으면 예외를 먹어버리고 정상 흐름으로 동작하게 된다.
      • 요구사항에 의해 로그는 어플리케이션 흐름에 영향을 주면 안된다.

 

 

• 요구사항 내용 중 level에 따른 출력, HTTP 요청 구분에 대한 내용은 구현이 안된 상황
  • 해당 요구사항을 만족하기 위해서 직전 로그의 level과 트랜잭션 ID를 알아야하기에 로그에 대한 문맥(Context) 정보를 넘겨줘야 한다.

---

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

@Slf4j
@Component
public class 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 예제
  • 나머지는 V1과 동일하며 beginSync()만 새로 추가
    • 로그 시작할 때 사용한 id, level을 다음 로그에 넘겨주는 기능
    • createNextId()로 id는 동일하고 level은 하나 증가시켜줬다.

---

로그 추적기 V2 - 적용

• V2에서 V1과 차이점
  • Controller->Service->Repository를 호출할 때마다 Status의 TraceId를 함께 넘겨줬다.
  • Controller는 첫 로그 시작이므로 begin()을 사용하고 나머지 Service, Repository에서는 beginSync()로 로그를 시작해서 id는 그대로 두고 level을 증가시켰다.
  • => 같은 HTTP 요청에 대해서 같은 트랜잭션ID가 사용되고 level에 따라 다르게 표현된다.
    요구 사항 모두 만족

 

• 문제점
  • HTTP 요청을 구분하고 level을 표현하기 위해서 TraceId 동기화가 필요
    • 동기화를 위해 관련 메소드의 모든 파라미터를 수정해야한다.
  • 로그 처음 시작 시 begin() 호출, 아닌 경우 beginSync()를 호출해야 한다.
    • Controller -> Service -> Repository 순서로 호출하는 것이 아닌 바로 Service를 호출하는 경우 파라미터로 넘길 TraceId가 없다.

---

정리

• 예외가 발생하거나 던진 예외를 받았을 때 다시 던져주지 않으면 예외를 먹어버리고 정상 흐름으로 동작하게 된다.
• try-catch로 예외 처리 시 try, catch 블럭 모두에서 사용하는 변수가 있는 경우 이전에 미리 선언하고 null로 초기화해줘야 한다.

---

출처 : [인프런 김영한 스프링 핵심 원리 - 고급편]

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/dashboard

스프링 핵심 원리 - 고급편 강의 | 김영한 - 인프런