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

[newh08]

강의 소개

우리는 기본편에서 스프링과 객체지향 개발의 기본기를 학습했음.
스프링을 더 잘 사용하기 위해선 세가지 핵심 원리를 알아야함.

• 스프링 핵심 디자인 패턴
• 동시성 문제와 쓰레드 로컬
• 스프링 AOP

1. 스프링 핵심 디자인 패턴
   스프링 내부 기술들은 몇가지 핵심 디자인 패턴으로 만들어져 있음
   스프링을 깊이있게 이해하기 위해선 스프링이 자주 사용하는 디자인 패턴을 알아야함.
   아래 패턴을 코드로 만들어보면서 학습해볼 예정

• 템플릿 메서드 패턴
• 전략 패턴
• 템플릿 콜백 패턴
• 프록시 패턴
• 데코레이터 패턴
  학습한 디자인 패턴을 애플리케이션에 적용하는 방법도 알아볼 예정.

2. 동시성 문제와 쓰레드 로컬
   웹 애플리케이션은 동시 여러 요청 처리를 위해 멀티 쓰레드를 사용하고,
   이에 따라 동시성 문제가 발생할 수 있음.
   발생할 수 있는 동시성 문제를 알아보고,
   이를 해결할 수 있는 쓰레드 로컬에 대해 알아볼 예정.

3. 스프링 AOP
   실무에서 정말 많이 사용함.
   스프링 AOP 의 기능 정리를 넘어
   동작 원리를 파해치고 실무에서 사용법과 주의사항까지 알아볼 예정.

예제 프로젝트 만들기 -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(1000);
        } 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(String itemId) {
        orderService.orderItem(itemId);
        return "ok";
    }
}

http://localhost:8080/v0/request?itemid=hello
이런식으로 요청하면 정상 반환하는것 확인 가능.
http://localhost:8080/request?itemid=ex
이렇게하면 에러 발생.

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

회사 입사후 수년간 운영중인 거대 프로젝트에 투입됨.
소스코드 수십만 라인, 클래스도 수백개
프로젝트 중간에 병목이 생기고있음,
어디서 발생하는지 로그를 통해 확인하려함.

정상 요청
[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: 예외 발생!

이런식의 로그를 작성하도록 하는게 목표.

요구사항

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

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

모든 로직에 직접 로그를 남겨도 되긴하지만, 너무 비효율적임
특히 트랜잭션 ID 와 깊이를 표현하는 방법은 기존 정보를 받아야하기 때문에 단순히 로그를 남긴다고 해결할 수 있는것이 아님.

로그 추적기를 개발해볼건데, 처음엔 뭘 하는지 잘 모를것임.
일단 코드를 따라 치다가 나중에 테스트코드를 실행할때 보면 어떤건지 감이 잡힐 것임.

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

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

로그 추적기는 트랜잭션 ID 와 깊이를 표현할 방법이 필요함.
여기서는 트랜잭션 ID 와 깊이를 표현하는 level 을 묶어 TraceId 를 만들었음.

[796bccd9] OrderController.request()
[796bccd9]     |-->OrderService.orderItem()
[796bccd9]     |    |-->OrderRepository.save()

Id 를 UUID 를 사용해 만들고, 로그정도에서 구분하는거니 앞에 8자리만 사용

깊이 증가를 표현하기 위해 createNextId() 메서드 생성

반대로 깊이 감소를 표현하기 위해 createPreviousId 메서드 생성

처음부터 이렇게 모든걸 다 설계해서 만들지 못한다!

개발 하다보면 만들어야 하는게 나올것임.

로그의 상태정보를 나타내는 TraceStatus

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

로그 시작하면 끝이 있어야함.
시작 시간만 알면 각 스텝마다의 시간 계산이 가능하다.

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

TraceId, TraceStatus 사용해 실제 로그 생성하고, 처리하는 기능 개발해보자.

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

• 로그를 정상 종료
• 파라미터로 시작 로그 상태를 전달받음. 이를 활용해 실행 시간 계산, 종료시에도 동일한 로그 메시지 출력
• 정상 흐름에서 호출

exception()

• 로그를 에외상황으로 종료
• 실행시간, 예외 정보를 포함한 로그 메시지 출력
• 예외가 발생했을 때 호출

complete()

• end 와 exception 에서 비슷한 로직을 동시에 처리

addSpace()
레벨에 따라 로그 메시지 만들어냄

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

아직 모든 요구사항을 만족하진 못함. 로그를 시작하고 종료하는것만 만족.

이를 사용하는 테스트

class HelloTraceV1Test {

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

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

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

이 코드에 앞으로 여러 기능을 넣을것이기 때문에 이 코드를 잘 이해해야 한다!!

[YuDeokRin]

오 빠르시군요 ...저도 지금 올릴려던 참이였는데