스프링 핵심원리 1 [예제 생성 및 요구사항 이해]

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

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

김영한님의 스프링 핵심 원리- 고급편을 기반으로 작성하였습니다.

 

이번 글에선 스프링 핵심 원리- 고급편에서 전반적으로 사용될 log 추적기 예제의 프로토타입을 만들어보겠습니다.

이후의 글에서는 이 예제를 점진적으로 Develop하며 스프링의 중요한 원리에 대해 파악해보려고합니다.

우선, 요구사항을 설명하겠습니다.

 

요구사항

여러분이 새로운 회사에 입사했는데, 수 년간 운영중인 거대한 프로젝트에 투입되었다. 전체 소스 코드는 수 십만 라인이고, 클래스 수도 수 백개 이상이다.
여러분에게 처음 맡겨진 요구사항은 로그 추적기를 만드는 것이다.
애플리케이션이 커지면서 점점 모니터링과 운영이 중요해지는 단계이다. 특히 최근 자주 병목이 발생하고 있다. 어떤 부분에서 병목이 발생하는지, 그리고 어떤 부분에서 예외가 발생하는지를 로그를 통해 확인하는 것이 점점 중요해지고 있다.

기존에는 개발자가 문제가 발생한 다음에 관련 부분을 어렵게 찾아서 로그를 하나하나 직접 만들어서 남겼다. 로그를 미리 남겨둔다면 이런 부분을 손쉽게 찾을 수 있을 것이다. 이 부분을 개선하고 자동화 하는 것이 여러분의 미션이다.

 

 

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

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

    - 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨(로그 예외도 try catch로 무시하는 등, 영향을 주면 안됨)

- 메서드 호출에 걸린 시간
- 정상 흐름과 예외 흐름 구분

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

- 메서드 호출의 깊이 표현
- HTTP 요청을 구분

    1) HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함

    2) 트랜잭션 ID (DB 트랜잭션과 무관, 요청의 in&out을 말하는 것), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트     랜잭션이라 함. 요청이 실제로 Serilaize하지 않기에, 요청이 섞여도 제대로 알 수 있도록.

 

 

예시

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

 

프로토 타입 생성

먼저 로그 추적기를 위한 기반 데이터를 가지고 있는 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);
        //UUID 앞 8자리만 짧게 자름. (너무 길다, 어차피 중복 잘 발생 x)
    }

    public TraceId createNextId() {//같은 요청에서, level(깊이)이 하나 증가
        return new TraceId(id, level + 1);
    }

    public TraceId createPreviousId() {//같은 요청에서, level(깊이)이 하나 감소
        return new TraceId(id, level - 1);
    }

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

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

TraceId 클래스

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

TraceId 는 단순히 id (트랜잭션ID)와 level 정보를 함께 가지고 있다.

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

UUID

TraceId 를 처음 생성하면 createId() 를 사용해서 UUID(네트워크상 중복되지 않는 식별자)를 만들어낸다. UUID가 너무 길어서 여기서는 앞 8자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다. 여기서는 이렇게 만들어진 값을 트랜잭션ID 로 사용한다.

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

 

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 : 시작시 사용한 메시지이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.

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

 

 

HelloTraceV1

@Slf4j
@Component//싱글톤으로 사용하기 위해 싱글톤 패턴을 써도 되지만, 스프링 빈으로 등록하면, 기본 싱글톤으로 사용 가능. 
public class HelloTraceV1 {

    private static final String START_PREFIX = "-->";//시작할때
    private static final String COMPLETE_PREFIX = "<--";//정상 complete 시
    private static final String EX_PREFIX = "<X-"; //예외는 x 를 표기하도록 

    //로그 시작, 로그 메세지를 파라미터로 받아서 시작로그 출력, 응답결과로 로그의 상태를 나타내는 traceStatus 반환
    public TraceStatus begin(String message) {//log를 찍고 trace
        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);
    }//예외로 인한 비정상 종료 표시(예외도 같이 파라미터로 넘긴다.


//- end() , exception() , 의 요청 흐름을 한곳에서 편리하게 처리한다. 실행 시간을 측정하고 로그를 남긴다.
    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& 예외 발생    |    |X
    
    private static String addSpace(String prefix, int level) {//3개의 prefix
        StringBuilder sb = new StringBuilder();
        for (int i = 0; i < level; i++) {
            sb.append((i == level - 1) ? "|" + prefix : "|   ");
        }
        return sb.toString();
    }

}

 

 

begin()

 public TraceStatus begin(String message) {
        TraceId traceId = new TraceId();//시작할 때마다 새로운 TraceId 시작
        Long startTimeMs = System.currentTimeMillis();//시작 시간 저장
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

complete()

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

 

 

아직 요청 내에서 traceId의 동기화, level에 관한 설정을 적용하지 않은 상태이다.

 

 

 

 

남은 문제

요구사항

모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력 애플리케이션의 흐름을 변경하면 안됨

로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨 메서드 호출에 걸린 시간
정상 흐름과 예외 흐름 구분

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

메서드 호출의 깊이 표현 

 

HTTP 요청을 구분

- HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함

- 트랜잭션 ID (DB 트랜잭션X)

 

아직 구현하지 못한 요구사항은 메서드 호출의 깊이를 표현하고, 같은 HTTP 요청이면 같은 트랜잭션 ID를 남기는 것이다.
이 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일이다.
예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem() 에서 로그를 남길 때 알아야한다. 

결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다.
정리하면 로그에 대한 문맥( Context ) 정보가 필요하다.

 

 

 

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

트랜잭션ID와 메서드 호출의 깊이를 표현하는 하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션ID 와 level를 포함한

TraceId를 다음 로그에 파라미터로 넘겨주면된다.( 커넥션 동기화의 가장 단순한 방법으로 커넥션을 파라미터로 넘겨주는 것처럼 )

 

추가된 코드

traceId의 transactionId는 받아와서 유지시키고, level은 1 증가시키는 메소드를 추가한다.

//traceId.transactionId는 받아와서 유지시키고, level은 1 증가시키는 메소드
    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
        TraceId nextId = beforeTraceId.createNextId();//level을 증가시킨다.
        Long startTimeMs = System.currentTimeMillis();//시작시간 저장
        log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
        return new TraceStatus(nextId, startTimeMs, message);
    }

 

실행 로그를 보면 같은 트랜잭션ID 를 유지하고 level 을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다.

 

이제 서비스 영역에서, 구성한 로그 trace 로직을 간단한 애플리케이션에 적용하자.

애플리케이션은 간단하게 Controller - Service - Repository로 구성했다.

 

 

Controller

@RestController
@RequiredArgsConstructor
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);// traceId를 파라미터로 넘긴다.
            trace.end(status); //로그 종료
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);//예외 로그 출력
            throw e;//예외를 꼭 다시 던져주어야 한다.
        }
    }
}

 

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 {
        //자신의 호출자의 traceId를 받아오고, level 증가
            status = trace.beginSync(traceId, "OrderService.orderItem()");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);//로그 종료
        } catch (Exception e) {
            trace.exception(status, e);//예외 로그 출력
            throw e;
        }

    }
}

Repository

package hello.advanced.app.v2;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV2;
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 {
        //자신의 호출자의 traceId를 받아오고, level 증가
            status = trace.beginSync(traceId, "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();
        }
    }
}

 

최초 호출에만 begin()을 사용해 새로운 TraceId를 형성하여 처음부터 시작하게되고, 

이후에 Controller -> Service -> Repository 에서는 각각 

trace.end(), 혹은 trace.exception() 으로 수행된 로그를 종료 후 출력한다.

 

흐름

정상 로그

 

예외 로그

 

요구사항

모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력 애플리케이션의 흐름을 변경하면 안됨

로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨 메서드 호출에 걸린 시간
정상 흐름과 예외 흐름 구분

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

메서드 호출의 깊이 표현 

 

HTTP 요청을 구분

- HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함

- 트랜잭션 ID (DB 트랜잭션X)

실행 로그를 보면 같은 HTTP 요청에 대해서 트랜잭션ID가 유지되고, level도 잘 표현되는 것을 확인할 수 있다.

 

컨트롤러마다 HTTP 요청을 각각 받는데, 컨트롤러 레벨에서 beginsync() 메소드로 traceId를 유지시키고, 호출될 때마다 level을 증가시키는 것으로, 깊이도 표현하게 되었다.

또한, @Component를 통해, 로그를 수행하는 HelloTrace2를 싱글톤 빈으로 스프링 컨테이너가 관리하게 만들었다.

 

남은 문제

HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다.

현재는 TraceId 의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.

만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다.

만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황이라면 파리미터로 넘길 TraceId 가 없다.

 

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

 

이번 스프링 핵심원리-고급편에 관련된 포스팅에서는, 이러한 로그 예제를 개선하는 것으로 중요한 지식들을 학습, 체득하는 글들을 작성할 예정이기에, 이후의 글들에 사용될 예제 형성에 대해 간략하게 설명하였습니다.