로그 추적기 만들기

김상운(개발둥이)·2022년 7월 5일
1
post-thumbnail

스프링 핵심 원리

인프런 김영한님의 '스프링 핵심 원리-고급편' 강의 보러가기
https://www.inflearn.com/course/%EC%8A%A4%ED%94%84%EB%A7%81-%ED%95%B5%EC%8B%AC-%EC%9B%90%EB%A6%AC-%EA%B3%A0%EA%B8%89%ED%8E%B8/dashboard


요구 사항

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

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

    • 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨
  • 메서드 호출에 걸린 시간

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

    • 예외 발생시 예외 정보가 남아야 함
  • 메서드 호출의 깊이 표현

  • HTTP 요청을 구분

    • HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야함
    • 트랜잭션 ID (DB 트랜잭션X), 여기서는 하나의 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: 예외 발생!

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


TraceId

package hello.advanced.trace;

import java.util.UUID;

public class TraceId {

    private String id;
    private int level;

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

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

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

TraceId 클래스

로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다.
여기서는 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId 라는 개념을 만들었다.

TraceId 는 단순히 id (트랜잭션ID)와 level 정보를 함께 가지고 있다.
[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자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다. 여기서는 이렇게 만들어진 값을 트랜잭션ID
로 사용한다.
ab99e16f-3cde-4d24-8241-256108c203a2 //생성된 UUID
ab99e16f //앞 8자리만 사용

createNextId()

다음 TraceId 를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다. 대신에 깊이가 하나
증가한다.
실행 코드: new TraceId(id, level + 1)

[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID가 같다. 깊이는 하나 증가한다.

따라서 createNextId() 를 사용해서 현재 TraceId 를 기반으로 다음 TraceId 를 만들면 id 는 기존과
같고, level 은 하나 증가한다.

createPreviousId()

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

isFirstLevel()

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


TraceStatus

package hello.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;
    }
}

TraceStatus 클래스

로그의 상태 정보를 나타낸다.
로그를 시작하면 끝이 있어야 한다.

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

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

  • traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
  • startTimeMs : 로그 시작시간이다. 로그 종료시 이 시작 시간을 기준으로 시작~종료까지 전체 수행 시간을 구할 수 있다.
  • message : 시작시 사용한 메시지이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.
    TraceId , TraceStatus 를 사용해서 실제 로그를 생성하고, 처리하는 기능을 개발해보자.

로그 추적기 구현(파라미터 동기화)

package hello.advanced.trace.HelloTraceV1;

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

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

    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
//        TraceId traceId = new TraceId();
        TraceId nextId = beforeTraceId.createNextId();
        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();
    }

}

begin

메서드의 메인 로직 전에 호출할 메서드이다. begin 은 호출 깊이가 0인 메서드에서만 실행된다. 다음 호출된 메서드에서는 동일한 Id 를 갖도록 해야하기 때문이다. 생성한 Id 와 message 를 출력한다.

beginSync

begin 과 마찬가지로 메서드 시작시 호출할 메서드이다. 대신 상위 메서드에서 생성한 TraceId 를 파라미터로 받는다. 동일한 Id를 갖으므로 TraceId 의 level 만 1을 증가시켜서 사용한다. Id 와 message를 출력한다.

end

메서드의 메인 로직이 끝나고 정상적으로 종료되었을 경우 호출하는 메서드이다. complete 를 호출한다.

exception

메서드에서 예외가 발생해 비정상 종료되었을 경우 호출하는 메서드이다. complete 를 호출한다.

complete

메서드 종료시 공통적으로 호출하는 메서드이다. 정상 종료시 현재 level 에서 id, 소요시간, 메시지를 출력한다. 비정상 종료시 동일한 정보와 추가로 예외를 출력한다.


로그 추적기 적용

controller

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderServiceV2;
    private final HelloTraceV2 trace;

    @GetMapping("/v2/request")
    public String request(String itemId) {
        TraceStatus status = null;

        try {
            status = trace.begin("OrderController.request()");
            orderServiceV2.orderItem(itemId, status.getTraceId());
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}
  • 컨트롤러에서 서비스로 문맥을 유지하기 위해 service 메서드를 호출 시 TraceId 객체를 파라미터로 넘긴다.
  • 로그 추적을 시작하는 로그 추적기의 begin 메서드를 실행한다.

service

package hello.advanced.v2;

import hello.advanced.trace.HelloTraceV1.HelloTraceV1;
import hello.advanced.trace.HelloTraceV1.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(String itemId, TraceId traceId) {
        TraceStatus status = null;

        try {
            status = trace.beginSync(traceId, "OrderService.orderItem()");
            orderRepository.save(itemId, status.getTraceId());
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }

    }

}
  • 서비스 계층에서 리포지토리 계층으로의 문맥을 유지하기 위해 repository 메서드를 호출 시 TraceId 객체를 파라미터로 넘긴다.
  • 로그 추적을 동기화 하는 로그 추적기의 beginSync 메서드를 실행한다.

repository

package hello.advanced.v2;

import hello.advanced.trace.HelloTraceV1.HelloTraceV1;
import hello.advanced.trace.HelloTraceV1.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {

    private final HelloTraceV2 trace;

    public void save(String itemId, TraceId traceId) {

        TraceStatus status = null;

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

            if (itemId.equals("ex")) {
                throw new IllegalArgumentException("예외 발생!");
            }
            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();
        }
    }


}
  • 로그 추적을 동기화 하는 로그 추적기의 beginSync 메서드를 실행한다.

남은 문제

  • HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다.
  • TraceId 의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.
    • 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
  • 로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다.
    • 만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황이라면 파리미터로 넘길 TraceId 가 없다.
profile
공부한 것을 잊지 않기 위해, 고민했던 흔적을 남겨 성장하기 위해 글을 씁니다.

0개의 댓글