[Spring] 스프링 코어 2 - 로그 추적기

로그 추적기를 만들어 보면서 스프링 핵심원리에 대해 조금 더 깊게 배워봅시다.

요구사항 

• public 메소드의 호출에 대한 응답 정보 로그 출력
• 비즈니스 로직의 동작에 영향을 주지 않게.
• 메소드 호출에 걸린 시간도 함께 출력
• 정상 흐름, 예외 흐름 구분 - 예외 발생 시 예외 정보 출력
• 메소드 호출의 깊이 표현  : level이 증가 할수록 깊이를 직관적으로 표현
• HTTP 요청 구분 : HTTP 요청 단위로 특정 ID를 남겨서 Client를 구분
  • 하나의 HTTP 요청의 시작과 끝을 하나의 ID로 묶도록

예시

 

로그를 적용할 단순 로직 생성

Controller / Service / Repository

Service

Repository

추후 로그생성기를 만들고 적용해볼 로직을 간단하게 만들어주었습니다. 코드에 대한 설명은 생략하도록 하겠습니다.

 

로그에 대한 정보를 저장할 객체 생성 - TraceId - ( id, level)

@Getter
public class TraceId {

    private String id;
    private int level;

 

여기서 ID는 Http 요청을 구분할 고유한 ID입니다. 생성자에서 createId 메소드를 사용해 고유한 8글자의 UUID를 부여해줍니다.

Level은 메소드 호출의 깊이를 표현하기 위해 사용되었습니다. 추후 로그의 상태를 저장할 객체 TraceStatus에서 level을 사용 깊이를 직관적 표현할 것입니다.

 

 

로그에 대한 상태를 저장할 객체 생성 - TraceStatus ( traceId, startTimeMs, message )

TraceStatus는 로그에 대한 정보인 TraceId, 로그의 시작시간인 startTimeMills, 로그 메시지인 message를 필드를 가집니다.

 

자 이제, 로그 추적기를 낮은 버전부터 순차적으로 만들어보면서 코드를 개선해봅시다.

 

HelloTraceV1

첫 번째 버전입니다.

첫 번째 버전에서의 로그 추적기는 아래와 같은 로직으로 진행됩니다.

로그의 시작(begin)  -> 1) 예외 발생 X (end)  ->   로그 출력   (complete)
                                 ->2) 예외 발생 (exception)  -> 로그 출력  (complete) 

 

공통적으로 로그의 시작에서 TraceStatus를 생성해서 리턴하고, 

 

1) 로직에서 예외가 발생하지 않고 무사히 통과하면 통과 메시지의 PREFIX와 메소드 Depth Level을 로그로 출력합니다.

2) 로직에서 예외가 발생하면 로그를 출력할 때에 예외 메시지의 PREFIX와 메소드 Depth Level, 예외 메시지를 로그로 출력합니다.

 

@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 startTimeMills = System.currentTimeMillis();

    log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);

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

// 1) 예외 발생 X
public void end(TraceStatus status) {
    complete(status, null);
}


// 2) 예외 발생 O
public void exception(TraceStatus status, Exception e) {
    complete(status, e);
}

• end() : 예외가 발생하지 않고 무사히 통과한 코드에서 실행하는 메소드, complete메소드에 parameter로 status와 함께 예외가 없으므로 Exception에는  null을 넘겨줍니다.
• exception() : 예외가 발생한 경우 실행하는 메소드, complete 메소드에 paramter로 status와 예외 e를 넘겨줍니다.

private void complete(TraceStatus status, Exception e) {
    Long stopTimeMs = System.currentTimeMillis();
    long resultTimeMs = stopTimeMs - status.getStartTimeMs();
    TraceId traceId = status.getTraceId();
	
    // 1) 예외 발생 X
    if (e == null) {
        log.info("[{}] {}{} time={}ms", traceId.getId(),
                addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
                resultTimeMs);
    } else { // 2) 예외 발생
        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();
}

• complete() : 로그를 실질적으로 출력하는 메소드 
  • 예외가 없는 경우 addSpace 메소드를 통해 메소드 깊이와 COMPELETE_PREFIX를 넘겨주어 메소드 깊이와 로직이 예외없이 진행 되었음을 로그로 직관적으로 표현합니다. 
  • 예외가 있는 경우  addSpace 메소드를 통해 메소드 깊이와 EX_PREFIX를 넘겨주어 메소드 깊이와 예외가 발생했음을 로그로 직관적으로 표현합니다.

테스트 코드로 테스트 해보면 잘 작동하는 것을 확인할 수 있습니다.

예외 없는 로직

예외 발생 로직

 

개발한 로그 추적기를 앞서 생성한 단순로직에 적용해봅시다.

 

로그 추적기 로직 적용

 

OrderControllerV1.java

Controller 적용

Service 적용

Repository 적용

 

남은 요구사항 

• public 메소드의 호출에 대한 응답 정보 로그 출력
• 비즈니스 로직의 동작에 영향을 주지 않게.
• 메소드 호출에 걸린 시간도 함께 출력
• 정상 흐름, 예외 흐름 구분 - 예외 발생 시 예외 정보 출력
• 메소드 호출의 깊이 표현  : level이 증가 할수록 깊이를 직관적으로 표현
• HTTP 요청 구분 : HTTP 요청 단위로 특정 ID를 남겨서 Client를 구분
  • 하나의 HTTP 요청의 시작과 끝을 하나의 ID로 묶도록

남은 요구사항(= Level 표현, 요청 구분)을 해결하기 위해서는 이전 로그에 대한 문맥 정보를 넘겨주어야 합니다. 

쉽게 말해서 Controller에서 현재 로그 상태 정보인 ID와 LEVEL을 다음 Service에 넘겨주고 Service는 이 정보를 Repository에게 넘겨주는 방식으로.

로그 추적기 V2 - 현재 로그 정보 파라미터 동기화

TraceV2

public TraceStatus beginSync(TraceId beforeTraceId, String message) {
    TraceId traceId = beforeTraceId.createNextId();
    Long startTimeMills = System.currentTimeMillis();
    log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);

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

public TraceId createNextId() {
    return new TraceId(id, level + 1);
}

• beginSync에서는 이전 TraceId를 새로 만들지 않고 (이전 TraceId).createNextId() 하여 새로운 TraceId를 생성합니다.
• 새로운 TraceId = ( 현재 Trace Id, level + 1 )

TestCode

class HelloTraceV2Test {

    @Test
    public void begin_end() throws Exception {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status = trace.begin("hello1");
        TraceStatus status1 = trace.beginSync(status.getTraceId(), "hello2");
        trace.end(status1);
        trace.end(status);
    }

    @Test
    public void begin_exception() throws Exception {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status = trace.begin("hello");
        TraceStatus status1 = trace.beginSync(status.getTraceId(), "hello2");
        trace.exception(status1, new IllegalStateException());
        trace.exception(status, new IllegalStateException());
    }
}

예외 X

예외 O

V2 로직에 적용 

Controller

@GetMapping("/v2/request")
public String request(@RequestParam String itemId) {

    TraceStatus status = trace.begin("OrderController.request()");

    try {
        orderService.orderItem(status.getTraceId(), itemId);
        trace.end(status);
        return "ok";
    } catch (Exception e) {
        trace.exception(status, e);
        throw e;
    }
}

• Service의 orderItem에 현재 TraceId를 넘겨줍니다.

Service

public void orderItem(TraceId traceId, String itemId) {

    TraceStatus status = trace.beginSync(traceId, "OrderService.orderItem()");

    try {
        orderRepository.save(status.getTraceId(), itemId);
        trace.end(status);
    } catch (Exception e) {
        trace.exception(status, e);
        throw e;
    }
}

• Controller에서 넘겨받은 traceId를 begin이 아닌 beginSync로 실행함으로써 이전의 TraceId를 동기화 하여 사용합니다.
• 마찬가지로 Repository에도 동기화된 traceId를 넘겨줍니다.

Repository

public void save(TraceId traceId, String itemId) {

    TraceStatus status = trace.beginSync(traceId, "OrderRepository.save()");

    try {
        if (itemId.equals("ex")) {
            throw new IllegalStateException("예외 발생");
        }
        sleep(1000);
        trace.end(status);
    } catch (IllegalStateException e) {
        trace.exception(status, e);
        throw e;
    }
}

• Repository계층에서도 Service에서 넘겨받은 TraceId를 beginSync로 이 전계층의 TraceId를 동기화 하여 사용합니다.

case1) 예외 발생 X

case2) 예외 발생

 

 

<정리>

• V1에서 처리하지 못한 요구사항들을 파라미터로 동기화 하여 처리함으로써 해결해보았는데, 가독성이나 유지보수면에서 좋은 코드라고 보긴 어려웠습니다. 
  • 로그를 처음 호출할 때 - begin(), 처음이 아닐 때 - beginSync() 를 호출해야 함. 
  • try/catch문 때문에 코드 가독성 떨어짐.
  • TraceId를 동기화해주기 위해 메소드의 파라미터를 수정해야 함. (유지보수의 어려움) 
  • 만약 OrderController가 아닌 다른 컨트롤러에서 OrderService를 호출하는 상황이라면, 파라미터로 넘길 TraceId를 또 만들어주어야함.
• 이어서 다음 포스팅에서 파라미터 동기화를 사용하지 않고 여러 디자인 패턴들을 도입해봄으로써 코드를 조금씩 고쳐나가 보겠습니다.

 

<참고 자료>

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