제육's 휘발성 코딩
article thumbnail
Published 2022. 6. 15. 01:58
[Advanced] 스프링 로그 추적기 구현 🔷 Spring/Advanced
반응형

프로젝트 생성

image

상품을 주문하는 프로세스로 가정하고, Controller , Service, Repository로 이어지는 흐름을 단순하게 만들어보자.

 

OrderRepositoryV0

package hello.advanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV0 {

  public void save(String itemId) {
    // 저장 로직
    if (itemId.equals("ex")) {
      throw new IllegalStateException("예외 발생!");
    }
    sleep(1000);
  }

  private void sleep(int millis) {
    try {
      Thread.sleep(millis);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
  }
}
  • 상품을 저장하는데 약 1초 정도 소요되며 ex 라는 파라미터 값이 들어오면 예외가 발생하는 상황을 가진 레포지토리를 생성하자.

 

OrderServiceV0

package hello.advanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV0 {

  private final OrderRepositoryV0 orderRepository;

  public void orderItem(String itemId) {
    orderRepository.save(itemId);
  }
}
  • 복잡한 비즈니스 로직을 제외하고 리포지토리에 위임하는 서비스를 만들자.

 

OrderControllerV0

package hello.advanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {

  private final OrderServiceV0 orderService;

  @GetMapping("/v0/request")
  public String request(String itemId) {
    orderService.orderItem(itemId);
    return "ok";
  }
}

 

로그 추적기

애플리케이션이 커지면서 모니터링과 운영이 중요해지고 있다. 따라서 병목 현상이 자주 발생하며, 이 문제가 어떤 부분에서 예외를 발생하는지 로그를 통해 확인하는 것 또한 중요해지고 있다. 다음 예제를 통해 요구사항을 알아보고 로그 추적기를 만들어보자.

 

요구사항

정상 요청
[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: 예외 발생!
  • 모든 public 메서드의 호출과 응답 정보를 로그로 출력
  • 애플리케이션의 흐름을 변경하면 안됨 (비즈니스 로직의 영향을 주지 않는다.)
  • 메서드 호출에 걸린 시간
  • 정상 흐름과 예외 흐름 구분
  • HTTP 요청 구분 (요청 단위로 특정 ID를 남겨서 하나의 트랜잭션과 같이 표현)

 

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

애플리케이션의 모든 로직에 직접 로그를 남겨도 되지만, 그것보다는 더 효율적인 개발 방법이 필요하다. 요구사항에 맞추어 애플리케이션에 효과적으로 로그를 남기기 위한 로그 추적기를 개발해보자.

 

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

  public 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;
  }
}
  • 로그 추적기는 트랜잭션 ID와 깊이를 표현하는 방법이 필요하다. 여기서는 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId라는 객체를 만들었다.

 

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 객체를 만들었다.

 

HelloTraceV1

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.TraceId;
import hello.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();
    }
}
  • begin, end, exception 메서드를 만들어보자.

 

HelloTraceV1Test

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

public class HelloTraceV1Test {

  @Test
  void begin_end() {
    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 - 적용

V0버전을 V1으로 새로 만든 후, 로그 추적기를 적용해보자.

 

HelloControllerV1

package hello.advanced.app.v1;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

  private final OrderServiceV1 orderService;
  private final HelloTraceV1 trace;

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

    TraceStatus status = null;
    try {
      status = trace.begin("OrderController.request()");
      orderService.orderItem(itemId);
      trace.end(status);
      return "ok";
    } catch (Exception e) {
      trace.exception(status, e);
      // 예외를 다시 던져주어야 한다.
      throw e;
    }
  }
}
  • throw e 를 다시 던져 주지 않으면, 여기서 예외를 잡고 정상흐름으로 동작하는 것을 막고 WAS에서 처리하기 위함이다. 서비스와 레포지토리도 동일하게 적용시키자.

 

image

  • 다음과 같이 로그 추적기가 정상, 예외 모두 출력되는 것을 볼 수 있다. 요구사항 중 메서드 호출의 깊이와 HTTP 요청 구분에 대한 내용을 V2에서 적용해보자.

 

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

 

HelloTraceV2

public TraceStatus beginSync(TraceId beforeTraceId, String message) {
  TraceId nextId = beforeTraceId.createNextId();
  Long startTimeMs = System.currentTimeMillis();
  log.info("[" + nextId.getId() + "] " + addSpace(START_PREFIX,
                                                  nextId.getLevel()) + message);
  return new TraceStatus(nextId, startTimeMs, message);
}
  • 기존 HelloTraceV1에서 V2를 복사한후 깊이를 표현하는 level을 증가시키는 메서드를 추가하자.

 

HelloTraceV2Test

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

public class HelloTraceV2Test {

  @Test
  void begin_end_level2() {
    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_level2() {
    HelloTraceV2 trace = new HelloTraceV2();
    TraceStatus status1 = trace.begin("hello1");
    TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
    trace.exception(status2, new IllegalStateException());
    trace.exception(status1, new IllegalStateException());
  }
}

image

  • 다음과 같이 HelloTraceV2에서 메서드 호출의 깊이를 표현할 수 있다.

 

로그 추적기 V2 - 적용

image

  • 이제 로그 추적기를 다음과 같이 애플리케이션에 적용해보자. TraceId 값을 유지하기 위해 모든 파라미터에 값을 넘겨주어야한다. OrderX V1을 V2로 복사하자.

 

OrderServiceV2

public void orderItem(TraceId traceId, String itemId) {
  TraceStatus status = null;
  try {
    status = trace.beginSync(traceId, "OrderService.orderItem()");
    //            orderRepository.save(itemId);
    orderRepository.save(status.getTraceId(), itemId);
    trace.end(status);
  } catch (Exception e) {
    trace.exception(status, e);
    throw e;
  }
}
  • 다음과 같이 beginSync 메서드에 traceId를 넣어주기 위한 파라미터를 받고, 레포지토리에 전달한다. 컨트롤러와 레포지토리 모두 동일한 방식으로 적용하자.

image

  • 다음과 같이 정상 동작하는 것을 확인할 수 있다.

 

남은 문제는 HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다. 즉, 모든 파라미터를 수정하는 방식이 있다. 파라미터를 넘기는 것 말고 다른 대안을 다음 포스팅에서 알아보자.

 

REFERENCES

 

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

반응형
저작자표시
profile

제육's 휘발성 코딩

@sasca37

포스팅이 좋았다면 "좋아요❤️" 또는 "구독👍🏻" 해주세요! 맞구독은 언제나 환영입니다^^

검색 태그

자바
AOP
자료구조
프로그래머스
스프링
javascript
이펙티브자바
자바스크립트
JPA
jpql

티스토리툴바