4 분 소요

 인프런 스프링 핵심원리 - 고급편을 학습하고 정리한 내용 입니다.

로그 추적기 V1 프로토타입에 이어 개선 시킨 V2를 개발해 보자.

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

트랜잭션ID와 메서드 호출의 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션ID와 level을 다음 로그에 넘겨주는 것이다.

현재 로그의 상태 정보인 트랜잭션ID와 level은 TraceId에 포함되어 있다.

따라서 TraceId를 다음 로그에 넘겨주면 된다.

이 기능을 추가한 HelloTraceV2를 개발해 보자.

HelloTraceV2

요구 사항을 만족하기 위해 내용을 추가할 것이기 때문에 HelloTraceV1을 복사해서 V2를 만든다.

1
2
3
4
5
6
7
8
9
10

// V2에서 추가  
public TraceStatus beginSync(TraceId beforTraceID, String message){  
    //TraceId traceId = new TraceId();  
    TraceId nextId = beforTraceID.createNextId(); // id는 유지시키면서 레벨만 1 업  
    long startTimeMs = System.currentTimeMillis();  
  
    log.info("[{}] {}{}",nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);  
    // 로그 출력  
    return new TraceStatus(nextId, startTimeMs, message);  
}

다음 메서드가 추가되었다.

  • 기존 TraceId에서 createNextId()를 통해 다음 ID를 구한다.
  • createNextId()의 TraceId생성 로직은 다음과 같다.
    • 트랜잭션ID는 기존과 동일하게 유지
    • 깊이를 표현하는 Level은 하나 증가한다.

전체 HelloTraceV2

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56

@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);  
    }  
  
    // V2에서 추가  
    public TraceStatus beginSync(TraceId beforTraceID, String message){  
        //TraceId traceId = new TraceId();  
        TraceId nextId = beforTraceID.createNextId(); // id는 유지시키면서 레벨만 1 업  
        long startTimeMs = System.currentTimeMillis();  
  
        log.info("[{}] {}{}",nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);  
        // 로그 출력  
        return new TraceStatus(nextId, 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();  
    }  
}

테스트 코드를 작성해 보자.

HelloTraceV2Test - 테스트

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

class HelloTraceV2Test {  
  
    @Test  
    void begin_test() {  
        HelloTraceV2 trace = new HelloTraceV2();  
        TraceStatus status1 = trace.begin("hello1");  
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");  
        trace.end(status2);  
        trace.end(status1);  
    }  
  
    @Test  
    void begin_exception() {  
        HelloTraceV2 trace = new HelloTraceV2();  
        TraceStatus status1 = trace.begin("hello1");  
        TraceStatus status2 = trace.beginSync(status1.getTraceId(),"hello1");  
        trace.exception(status2, new IllegalStateException());  
        trace.exception(status1, new IllegalStateException());  
    }  
}

처음에는 bigin()을 사용하고, 거기서 나온 TraceStatus로 그 다음부터는 beginSync() 를 사용하면 된다.

끝날 때는 역순으로 끝내준다.

다음과 같이 이제 트랜잭션ID를 유지하고, level을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다.

로그 추적기 V2 - 적용

이제 로그 추적기를 애플리케이션에 적용해보자.

v1 → v2로 복사를 하자.

private final HelloTraceV2 trace

HelloTraceV1 → HelloTraceV2로 변경해주자.

V2 적용하기

메서드 호출의 깊이를 표현하고, HTTP 요청도 구분해보자.

이렇게 하려면 처음 로그를 남기는 OrderController.request()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션ID를 사용했는지 다음 차례인 OrderServiec.orderItem()에서 로그를 남길 시점에 알아야 한다.

결국 현재 로그 상태 정보인 트랜잭션ID와 level이 다음으로 전달되어야 한다.

따라서 traceId를 컨트롤러에서 서비스를 호출할 때 넘겨주면 된다.

다음같이 넘겨줄 때 메서드 리팩토링 기능을 사용해서 추가해 주자..

OrderServiceV2

1
2
3
4
5
6
7
8
9
10
11
12

public void orderItem(TraceId traceId, String itemId) {  
  
    TraceStatus status = null;  
    try {  
        status = trace.beginSync(traceId, "OrderServiceV2.orderItem()");  
        orderRepository.save(status.getTraceId(),itemId);  
        trace.end(status);  
    } catch (Exception e) {  
        trace.exception(status, e);  
        throw e;  
    }  
}

다음과 같이 TraceId를 받았기 때문에 begin → beginSync로 변경해 준다.

또 리포지토리 단에도 TraceId를 넘겨줘서 거기 서도 beginSync를 사용하도록 변경한다.

V2 적용 결과.

http://localhost:8080/v2/request?itemId=hello

드디어 레벨이 잘 나온다.

예외도 한번 터트려 보자. http://localhost:8080/v2/request?itemId=ex

예외도 잘 레벨로 나온다.

정리

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

드디어 모든 요구 사항을 만족했다.

하지만 많은 문제들이 있다.

남은 문제

  1. HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId동기화가 필요하다.
  2. TraceId의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.
    1. 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
  3. 로그를 처음 시작할 때는 begin()을 호출하고, 처음이 아닐 때는 beginSync()를 호출해야 한다.
    1. 만약 컨트롤러를 통해 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출해야 하는 상황이라면 TraceId를 넘길 값이 없다.

결정적으로 이런 로그를 적용하기 위해서 모든 코드를 다 뜯어 고쳐야 했다.

댓글남기기

참고