스프링 핵심 원리 - 고급편_로그 추적기(요구사항 분석, 프로토타입 개발 V1)

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

• 애플리케이션이 커지면 모니터링과 운영이 중요해진다.
• 병목이 발생하면 어디서 발생하는지 로그를 통해 확인하는 것이 매우 중요하다.

요구사항

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

예시

정상 요청
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem()
[796bccd9] |   |-->OrderRepository.save()
[796bccd9] |   |<--OrderRepository.save() time=1004ms
[796bccd9] |<--OrderService.orderItem() time=1014ms
[796bccd9] OrderController.request() time=1016ms

예외 발생
[b7119f27] OrderController.request()
[b7119f27] |-->OrderService.orderItem()
[b7119f27] | |-->OrderRepository.save()
[b7119f27] | |<X-OrderRepository.save() time=0ms
ex=java.lang IllegalStateException: 예외 발생! 
[b7119f27] |<X-OrderService.orderItem() time=10ms 
ex=java.lang IllegalStateException: 예외 발생!
[b7119f27] OrderController.request() time=11ms 
ex=java.lang IllegalStateException: 예외 발생!

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

• 로그를 로직마다 직접 남겨도 되지만, 더 효율적인 방법이 필요하다.
• 특히 트랜잭션 ID와 깊이를 표현하는 방법은 기존 정보를 이어 받아야 하기 때문에 단순하게 로그만 직접 남겨서 해결할 수 있는 것은 아니다.

TraceId 예제

package com.example.advanced.trace;

import java.util.UUID;

public class TraceId {
    private String id;
    private int level;

    public TraceId(String id, int level) {
        this.id = id;
        this.level = level;
    }

    public TraceId() {
        this.id = createrId();
        this.level = 0;
    }

    private String createrId() {
        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;
    }
}

• 로그 추적기의 요구사항 중 하나는 트랜잭션 ID와 깊이를 표현하는 방법이었다.
• 트랜잭션 ID와 깊이를 표현하는 level을 묶어 TraceId라는 개념(클래스)를 생성했다.
• 단순하게 id와 깊이를 가지고 있다.

TraceStatus 예제

package com.example.advanced.trace;

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 TraceId getTraceId() {
        return traceId;
    }

    public Long getStartTimeMs() {
        return startTimeMs;
    }

    public String getMessage() {
        return message;
    }
}

• 로그 상태 정보를 나타내는 클래스
• 해당 클래스는 로그를 시작할 때 상태 정보를 가지고 있다.
  • 이 상태 정보는 로그 종료 시 사용

HelloTraceV1 예제

package com.example.advanced.trace.hellotrace;

import com.example.advanced.trace.TraceId;
import com.example.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

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

• 위 클래스를 통해 실제 로그 시작, 종료할 수 있다. 또한, 출력하고 실행 시간도 측정할 수 있다.
  • @Component를 통해 스프링 빈으로 등록하여 싱글톤으로 사용

공개 메서드

• TraceStatus begin(String message)
  • 로그를 시작
  • 로그 메시지를 파라미터로 받아서 시작 로그를 출력한다.
  • 응답 결과로 현재 로그 상태인 TraceStatus 반환
• void end(TraceStatus status)
  • 로그를 정상적으로 종료
  • 파라미터로 시작 로그의 상태(TraceStatus)를 전달 받아 실행 시간 계산 및 종료 시에도 시작 때와 동일한 로그 출력 가능
  • 정상 흐름에서 호출
• void exception(TraceStatus status, Exception e)
  • 로그를 예외 상황으로 종료
  • TraceStatus, Exception을 인자로 받아, 실행 시간, 예외 정보 포함한 로그 출력
  • 예외 발생 시 호출

비공개 메서드

• void complete(TraceStatus status, Exception e)
  • end(), exception()의 요청 흐름을 한곳에서 관리
  • 실행 시간 측정 및 로그 출력
• String addSpace(String prefix, int level)
  • 아래와 같은 결과 출력
    • -->
      • level 0:
      • level 1: |-->
      • level 2: | |-->
    • <--
      • level 0:
      • level 1: |<--
      • level 2: | |<--
    • <X-
      • level 0:
      • level 1: |<X-
      • level 2: | |<X-

테스트 작성

public class HelloTraceV1Test {

    @Test
    void begin_enc() {
        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());
    }
}

• begin_end() 로그
• 19:21:31.752 [main] INFO com.example.advanced.trace.hellotrace.HelloTraceV1 -- [f1e27ceb] hello 19:21:31.752 [main] INFO com.example.advanced.trace.hellotrace.HelloTraceV1 -- [f1e27ceb] hello time=0ms
• begin_exception() 로그
• 19:21:31.719 [main] INFO com.example.advanced.trace.hellotrace.HelloTraceV1 -- [a3a5f4d8] hello 19:21:31.726 [main] INFO com.example.advanced.trace.hellotrace.HelloTraceV1 -- [a3a5f4d8] hello time=8ms ex=java.lang.IllegalStateException
• 참고
  • 실제 테스트 코드는 자동으로 검증하는 과정이 필요 (Assertions.assert 등)
  • 위 테스트는 결과를 콘솔로 직접 확인이 필요함.
  • 응답값이 없는 경우 자동으로 검증하려면 여러 테스트 기법이 필요하지만, 예제 단순화를 위해 검증 테스트 생략

 

출처: 김영한 지식공유자의 스프링 핵심 원리 고급편