6 분 소요

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

이전에 생성한로그 추적기를 구현해 보자.

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

애플리케이션에 모든 로직에 직접 로그를 남겨도 되지만, 그것보다는 더 효율적인 개발 방법이 필요하다.

특히 트랜잭션 ID와 깊이를 표현하는 방법은 기존 정보를 이어 받아야 하기 때문에 단순히 로그만 남긴다고 해결할 수 있는 것은 아니다.

먼저 프로토타입 버전 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId, TraceStatus 클래스를 만들어보자.

해당 패키지에 만들겠다.

TraceId

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

@Getter  
public class TraceId {  
  
    private String id;  
    private int level;  
  
    public TraceId() {  
        this.id = createId();  
        this.level = 0;  
    }  
  
    private TraceId(String traceId, int level) {  
        this.id = traceId;  
        this.level = level;  
    }  
  
    private String createId() {  
        // uuid 생성해서 앞에 8자리만 사용  
        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;  
    }  
}

TraceId 클래스

로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다.

여기서는 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId라는 개념을 만들었다.

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

1
2
3

[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자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다.

1
2

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

createNextId()

다음 TraceId를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다. 대신에 깊이가 하나 증가한다.

createPreviousId()

createNextId()의 반대 역할을 한다. id는 기존과 같고, level은 하나 감소한다.

isFirstLevel()

첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드

TraceStatus

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

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

TraceStatus 클래스: 로그의 상태 정보를 나타낸다.

로그를 시작하면 끝이 있어야 한다.

1
2

[796bccd9] OrderController.request() //로그 시작 
[796bccd9] OrderController.request() time=1016ms //로그 종료

TraceStatus는 로그를 시작할 때의 상태 정보를 가지고 있다. 이 상태 정보는 로그를 종료할 때 사용된다.

  • traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
  • startTimems : 로그 시작 시간이다. 로그 종료 시 이 시작 시간을 기준으로 시작 - 종료 까지 전체 수행 시간을 구할 수 있다.
  • message : 시작 시 사용한 메시지 이다. 이후 로그 종료 시에도 이 메시지를 사용해서 출력한다.

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

HelloTraceV1

hello.advanced.trace.hellotrace.HelloTraceV1

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

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

HelloTraceV1을 사용해서 실제 로그를 시작하고 종료할 수 있다. 그리고 로그를 출력하고 실행 시간도 측정할 수 있다.

  • @Component : 싱글톤으로 사용하기 위해 스프링 빈으로 등록한다. 컴포넌트 스캔의 대상이 된다.
  • TraceStatus begin(String message)
    • 로그를 시작한다.
    • 로그 메시지를 파라미터로 받아서 시작 로그를 출력한다.
    • 응답 결과로 현재 로그의 상태인 TraceStatus를 반환한다.
  • void end(TraceStatus status)
    • 로그를 정상 종료한다.
    • 파라미터로 시작 로그의 상태(TraceStatus)를 전달 받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료 시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
  • void exception(TraceStatus status, Exception e)
    • 로그를 예외 상황으로 종료한다.
    • TraceStatus, Exception 정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.
    • 예외가 발생할 때 호출한다.
  • complete(TraceStatus status, Exception e)
    • 비공개 메서드
    • end(), exception(), 의 요청 흐름을 한 곳에서 편리하게 처리한다. 실행 시간을 측정하고 로그를 남긴다.
  • String addSpace(String prefix, int level) : 다음과 같은 결과를 출력한다.
    • prefix: -->
      • level 0: ``
      • level 1: |-->
      • level 2: | |-->
    • prefix: <--
      • level 0: ``
      • level 1: |<--
      • level 2: | |<--
    • prefix: <x-
      • level 0: ``
      • level 1: |<X-
      • level 2: | |<x-

테스트 작성

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

class HelloTraceV1Test {  
  
    @Test  
    void begin_test() {  
        HelloTraceV1 trace = new HelloTraceV1();  
        TraceStatus status = trace.begin("hello");  
        trace.end(status);  
    }  
  
    @Test  
    void begin_exception() {  
        HelloTraceV1 trace = new HelloTraceV1();  
        TraceStatus status = trace.begin("hello");  
        trace.exception(status, new IllegalStateException());  
    }  
}

다음과 같이 트랜잭션 아이디와 시작, 종료 실행 시간이 잘 나온다 (이건 사실 테스트가 아니라 그냥 확인 용)

로그 추적기 V1 - 적용

로그를 로직에 적용하기 위해

기존에 있던 코드들을 v1 패키지에 복사 한다.

이제 컨트롤러, 리포지토리, 서비스단에 로그 추적기를 적용해 보자.

컨트롤러

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

@RestController  
@RequiredArgsConstructor  
public class OrderControllerV1 {  
  
    private final OrderServiceV1 orderService;  
    private final HelloTraceV1 trace;  
  
    @GetMapping("/v1/request")  
    public String request(@RequestParam("itemId") String itemId) {  
  
        TraceStatus status = null;  
        try {  
            status = trace.begin("OrderControllerV1.request()");  
            orderService.orderItem(itemId);  
            trace.end(status);  
            return "ok";  
  
        } catch (Exception e) {  
            trace.exception(status, e);  
            throw e;  
        }  
    }  
}

1

status = trace.begin("OrderControllerV1.request()");

이걸로 로그를 시작한다.

1
2

//로직 정상 종료 후
trace.end(status);

로그를 종료한다.

1
2
3
4

catch (Exception e) {  
	trace.exception(status, e);  
	throw e;  
}

예외가 터지면 예외 로그를 출력한다.

서비스

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

@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("OrderServiceV1.orderItem()");  
            orderRepository.save(itemId);  
            trace.end(status);  
        } catch (Exception e) {  
            trace.exception(status, e);  
            throw e;  
        }  
    }  
}

컨트롤러와 마찬가지로 예외를 감쌀 try~catch를 만들고, 로직 사이에 begin end, 그리고 catch에 exception을 위치 시켰다.

리포지토리

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

@Repository  
@RequiredArgsConstructor  
public class OrderRepositoryV1 {  
  
    private final HelloTraceV1 trace;  
  
    public void save(String itemId) {  
  
        TraceStatus status = null;  
        try {  
            status = trace.begin("OrderRepositoryV1.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(long millis) {  
        try {  
            Thread.sleep(millis);  
        } catch (InterruptedException e) {  
            e.printStackTrace();  
        }  
    }  
}

컨트롤러, 서비스와 마찬가지이다.

실제 적용

정상적인 흐름일 때 다음과 같이 로그가 나온다.

예외가 터지면 다음과 같이 흐름이 진행 되고, 마지막에 컨트롤러에서도 throw e를 했기 때문에 톰캣에서도 로그를 띄운다.

남은 요구 사항

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

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

이 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일이다. 예를 들어서 OrderController.request()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는 지를 그 다음에 로그를 남기는 OrderService.orderItem()에서 알아야 한다.

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

정리하면 로그에 대한 문맥(Context) 정보가 필요하다.

댓글남기기

참고