[Spring] 스프링 핵심 원리 - 고급편 섹션1 예제 만들기

 

본 내용은 인프런 김영한T 스프링 DB 2편 - 데이터 접근 활용 기술 강의를 공부하고 정리한 내용입니다:)

⬜ 섹션11 스프링 트랜잭션 전파2 - 활용

◼️ 예제 프로젝트 만들기

실습을 위해 간단한 코드를 짜보자.

만드는 프로그램은 아주 간단한 상품주문 프로젝트이다. Controller→Service →Repository 흐름을 가졌다.

@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(String itemId) {
        orderService.orderItem(itemId);
        return "ok";
    }
}

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

🟢요구사항

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

프로젝트에 초청된 나! 위 요구사항을 토대로 로그 추적기를 만들어달라는 미션을 받았다~

사실 모니터링 툴을 도입하면 많은부분이해결되지만...학습에 초점을두자..

미리 완성 결과를 보자면 아래와 같다. 여기서 한가지 포인트는, 예외가 들어와도 흐름에 영향을 주지않고 로그도 성공적으로 마무리하는것!

🟦 로그 추적기 - 미리보는 결과

정상 로그

예외 발생시 로그

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

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

    //ab99e16f-3cde-4d24-8241-256108c203a2 //생성된 UUID
    // ab99e16f //앞 8자리만 사용
    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;
    }
}

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 Long getStartTimeMs() {
        return startTimeMs;
    }
    public String getMessage() {
        return message;
    }
    public TraceId getTraceId() {
        return traceId;
    }
}

@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); // end(),exception() 요청 흐름을 한 곳에서 처리
    }

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

◼️ 로그 추적기 V1 - 적용

위에서 앞서 개발한 HelloTraceV1을 적용해보자.단순하게 trace.begin(), trace.end() 코드 두 줄만 적용하면 될 줄 알았지만, 실상은 그렇지 않다. 

• trace.exception()으로 예외까지 처리해야 하므로 지저분한 try-catch 코드가 추가된다.
• TraceStatus status 변수를 빼내야한다.
• 또한 throw e로 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 로그는 애플리케이션에 흐름에 영향을 주면 안된다. (로그 때문에 예외가 사라지면 안된다!)

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

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

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderServiceV1 orderService;
    private final HelloTraceV1 trace;

    @GetMapping("/v1/request")
    public String request(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; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

그림으로 보는 로그 흐름. 아직 level,트랜잭션ID 유지 부분은 개발하지 않았다.

🟢남은 문제

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

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

트랜잭션ID와 level 은 TraceId에 포함되어있다. 위 남은 문제 해결을 위해, TraceId를 다음 로그에 넘겨주면 된다.

beginSync()는 기존 TraceId에서 createNextId()를 통해 다음 ID를 구한다.

여기서 트랜잭션 ID는 유지하되, level은 하나 증가한다.

@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);
    }
    
    //추가한 부분
    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);
    }
    //..기존 코드 생략
}

◼️ 로그 추적기 V2 - 적용

처음에는 begin(...),이후 beginSync(...)를 사용한다. beginSync(...) 를 호출할땐 직전 로그의 traceId정보(트랜잭션id,level)를 넘겨준다. beginSync(...) 는 내부에서 다음 traceId를 생성하면서 트랜잭션ID는 유지하고 level은 하나 증가시킨다.

 

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

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

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

@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);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

🟢남은 문제

HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요한데, 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다. 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.

 

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