로그 추적기

로직을 수행할 때 어떤 로직들을 호출하는지, 에러는 어디서 나는지 확인을 하기 위해 로그로 남기는 것을 로그 추적기라고 한다.

 

로그 추적기는 로그만 출력하는 용도로 사용해야하며 애플리케이션에 영향을 끼치면 안된다. 예를 들어 try-catch문을 사용할 때 로그 추적기에서 예외를 처리하면 안되고, throw e를 통해 예외를 던져야만 한다.

 

로그에 들어가는 내용은 traceId와 traceStatus이다. traceId는 UUID로 로직을 수행할 때 같은 요청임을 표시해주기 위함이다. traceStatus는 로직의 시간, 메시지, traceId를 전달한다.

 

 

TraceId

@Getter
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); // 0부터 8자리까지 자르기
    }

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

createId()는 새로운 UUID를 만들어준다. createNextId()는 레벨을 1씩 증가시켜주는 함수이다.

 

 

TraceStatus

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

 

 

traceId를 가지고 시작(begin), 끝(end), 예외(exception) 시 로그를 출력해주는 로직이다.

@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 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()은 맨 처음 단계에서 UUID가 생성되는 과정이고, beginSync는 다른 로직들이 실행될 때 traceId를 받아오기 위한 함수이다.

예를 들어 begin()을 컨트롤러에서 호출한다고 가정할 때, 생성된 traceId는 하나로 유지 되어야하기 때문에 Service, Repository 계층에서는 beginSync로 각각 호출시키는 위치의 traceId를 받아온다.

 

complete 메서드는 파라미터가 2개가 존재하는데, 첫 번째 파라미터만 입력하면 end()가 호출되고, 두 번째 파라미터인 예외까지 입력하면 exception()이 호출된다.

 

addSpace는 호출되는 로직의 레벨을 표현하기 위함이다.

 

 

 

 

실제 호출 과정

 

Controller

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

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

        TraceStatus status = null;

        try {
            status = trace.begin("OrderController.request()");
            orderService.orderItem(status.getTraceId(), itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 꼭 다시 던져주어야 한다.
        }
    }
}

begin()을 통해서 UUID를 생성하고, status의 getTraceId()를 service 계층으로 넘겨준다. try - catch문을 통해 에러가 없을 때에는 end()로직을, 예외가 있을 때에는 에러를 포함한 exception()로직을 호출한다.

 

 

Service

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(TraceId traceId, String itemId) {

        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderService.request()");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 꼭 다시 던져주어야 한다.
        }
    }
}

Controller에서 받아온 traceId를 trace.beginSync()에 넣어줘서 로그에 뜨는 traceId가 일치하게 만들어준다. 여기에서도 예외가 발생하는지 아닌지에 따라 end(), exception()이 각각 호출된다.

 

 

Repository

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {

    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {

        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderRepository.request()");

            if (itemId.equals("ex")) {
                throw new IllegalArgumentException("예외 발생!");
            }
            sleep(100);

            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 꼭 다시 던져주어야 한다.
        }
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

Service 계층에서 traceId를 받아와서 beginSync로 사용하고 예외가 발생했는지 확인해서 해당 로직을 호출한다.

 

실제 호출된 로그이다. 각각의 end타임에서 소요 시간을 출력해주고, 로그를 통해 어떤 로직들이 호출되는지를 확인시켜준다.

 

addSpace를 통해 로직에 따라 level별로 띄어쓰기를 하며 어떤 로직인지 알기 쉽게 해준다.

 

예외가 발생했을 때에는 예외가 발생했다고 로그로 알려준다.

 

 

로그 추적기를 사용하면 어디에서 예외가 발생했는지 쉽게 알 수 있기 때문에 예외가 많이 발생하는 곳에서는 로그 추적기를 만들어서 로그를 통해 코드에서의 오류가 있는지 확인하는 것이 효율적이다.