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

[YONGHYNG]

로그 추적기 V1 - 적용

OrderControllerV1

package hello.advanced.app.v1;

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

@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; //예외를 다시 던져줘야 함
        }
    }
}

• HelloTraceV1 trace: HelloTraceV1을 주입 받음, HelloTraceV1은 @component 애노테이션을 가지고 있어 컴포넌트 스캔의 대상이 됨, 따라서 자동으로 스프링 빈으로 등록
• trace.begin("OrderController.request()") : 로그를 시작할 때 메시지 이름으로 컨트롤러 이름 +
  메서드 이름 줌, 이렇게 하면 어떤 컨트롤러와 메서드가 호출되었는지 로그로 편리하게 확인 가능
  , 수작업인 것이 단점
• 단순하게 trace.begin() , trace.end() 코드 두 줄만 적용하면 될 줄 알았지만, 실상은 그렇지 않음,
  trace.exception() 으로 예외까지 처리해야 하므로 지저분한 try , catch 코드가 추가
• begin() 의 결과 값으로 받은 TraceStatus status 값을 end() , exception() 에 넘김 결국
  try , catch 블록 모두에 이 값을 넘김, 따라서 try 상위에 TraceStatus status 코드를 선언해야 함 만약 try 안에서 TraceStatus status 를 선언하면 try 블록안에서만 해당 변수가 유효하기 때문에 catch 블록에 넘길 수 없음 따라서 컴파일 오류가 발생
• throw e : 예외를 꼭 다시 던져야함 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작 로그는 애플리케이션에 흐름에 영향을 주면 안 됨 로그 때문에 예외가 사라지면 안됨

OrderServiceV1

package hello.advanced.app.v1;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV1;
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.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV1;
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")) {
                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();
        }
    }
}

정상 실행 로그

-- level 관련 기능 개발하지 않음, 따라서 level 항상 0 트랜잭션 ID 값도 다름, 개발 안 함

예외 실행 로그

남은 문제

요구사항

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

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

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

• 메서드 호출에 걸린 시간

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

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

• 메서드 호출의 깊이 표현

• HTTP 요청을 구분

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

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

• 아직 구현하지 못한 요구사항은 메서드 호출의 깊이를 표현하고, 같은 HTTP 요청이면 같은 트랜잭션 ID를 남기는 것

• 이 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일

1. 예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem() 에서 로그를 남길 때 알아야 함
2. 결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 함, 정리하면 로그에 대한 문맥 정보 필요.

필드 동기화 - 개발

• 앞서 로그 추적기를 만들면서 다음 로그를 출력할 때 트랜잭션ID와 level을 동기화 하는 문제 발생
• 위 문제를 해결하기 위해 TraceId를 파라미터로 넘겼음 -> 동기화 성공 -> 하지만 모든 메서드에 TraceId 파라미터를 추가해야 하는 문제 발생 -> 해결 방법은?

LogTrace 인터페이스

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceStatus;

public interface LogTrace {
    
         TraceStatus begin(String message);
         void end(TraceStatus status);
         void exception(TraceStatus status, Exception e)
}

• 로그 추적기를 위한 최소한 기능, begin(), end(), exception() 정의

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@Slf4j
public class FieldLogTrace implements LogTrace {

    private static final String START_PREFIX= "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";

    private TraceId traceIdHolder; //traceId 동기화, 동시성 이슈 발생

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder;
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);

        return new TraceStatus(traceId, startTimeMs, message);
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }

    @Override
    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 ex={}",traceId.getId(),
                    addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs,
                    e.toString());
        }
        releaseTraceId();
    }
    private void syncTraceId(){
        if(traceIdHolder == null){
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

    private void releaseTraceId(){
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

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

• FieldLogTrace는 기존에 만들었던 HelloTraceV2와 거의 같은 기능을 함
• TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceIdHolder 필드를 사용하도록 변경
• 이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHolder에 저장
• 여기서 중요한 부분은 로그를 시작할 때 호출하는 **syncTraceId()**와 로그를 종료할 때 호출하는 releaseTraceId() 임

syncTraceId()

• TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가
• 최초 호출이면 TraceId를 새로 만듬
• 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level도 하나 증가
• 결과를 traceIdHolder에 보관

releaseTraceId()

• 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소 필요
• releaseTraceId()는 level을 하나 감소 시킴
• 만약 최초 호출(level==0)이면 내부에서 관리하는 traceId 제거

FieldLogTraceTest

pacakage hello.advanced.trace.logtrace;

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

class FieldLogTraceTest {
    FieldLogTrace trace = new FieldLogTrace();

    @Test 
    void begin_end_level2() {
           TraceStatus status1 = trace.begin("hello1");
           TraceStatus status2 = trace.begin("hello2");
           trace.end(status2);
           trace.end(status1);
    }
    @Test
    void begin_exception_level2() {
            TraceStatus status1 = trace.begin("hello");
            TraceStatus status2 = trace.begin("hello2");
            trace.exception(status2, new IllegalStateException());
            trace.exception(status1, new IllegalStateException());    
    }
}

begin_end_level2() - 실행 결과

begin_exception_level2() - 실행 결과

• 트랜잭션ID도 동일하게 나옴, level을 통한 깊이도 잘 표현
• FieldLogTrace.traceIdHolder 필드를 사용, TraceId가 잘 동기화 되는 것 확인 가능
• 이제 불필요하게 TraceId를 파라미터로 전달하지 않아도 되고, 애플리케이션의 메서드 파라미터도 변경하지 않아도 됨