스프링 핵심 원리 고급편 - 로그 추적기 프로젝트 만들기

최준호·2022년 8월 6일
Spring
0

Spring

목록 보기
35/48
post-thumbnail
post-custom-banner

참고로 강의는 Intellij로 시작하지만 나는 VSC로 시작한다. 그 이유는 회사에서 VSC를 쓰기 때문... 나도 Intellij 쓰고 싶다... 팀 내에서 Java보다 node, python, ts 등 사용하는 언어들의 개발툴을 통일하다 보니 vsc가 제일 적합했다 ㅜㅜ

참고 김영한 강사님의 스프링 핵심 원리 - 고급편

👏 프로젝트 생성

Spring boot 시작 프로젝트 스펙

  • Gradle
  • Java 11
  • 2.7.2
  • package 설정
    - hello.advanced
  • Dependencies
    - Spring Web
    - Lombok

뜨면 정상 실행 완료.

✍️ 예제 프로젝트 소스 작성하기

@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라는 상품은 예외가 발생하는 repository를 작성했다.

@Service
@RequiredArgsConstructor
public class OrderServiceV0 {
    private final OrderRepositoryV0 orderRepository;

    public void orderItem(String itemId) {
        orderRepository.save(itemId);
    }
}

해당 repository를 사용하는 service를 작성했다.

좀더 객체지향적으로 설계하려면 interface가 껴야하지만 간단하게 구현하는거니까 패스

@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {
    private final OrderServiceV0 orderService;

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

마지막 controller까지 작성했다.

✅ 확인하기

http://localhost:8080/v0/request?itemId=item url로 요청을 해보자

정상 실행되었고

http://localhost:8080/v0/request?itemId=ex 요청해보면

에러 페이지와

에러 코드를 확인할 수 있다.

👏 로그 추적기 시작!

📄 요구사항

새로운 회사에 투입되었다. 수 년간 운영중인 거대한 프로젝트였고 소스는 수십만 라인에 클래스도 수백개 이상이다. 우리에게 맡겨진 첫 요구사항은 로그 추적기를 만드는 것이다.

application이 커지면서 점점 모니터링과 운영이 주용해지는 단계이다. 특히 최근 자주 병목 현상이 발생하고 있다. 어떤 부분에서 병목이 발생하는지, 그리고 어떤 부분에서 예외가 발생하는지 로그를 통해 확인할 수 있는 로그 추적기를 만드는 것이 우리의 첫 요구사항이다.

병목현상은 bootle neck으로 병의 목부분을 의미한다. 넓은 길이가 갑자기 좁아짐으로써 갑자기 성능의 저하를 의미하는 현상으로 IT쪽에서는 많은 양의 데이터가 한번에 유입됨으로써 성능이 저하되는 현상을 의미한다.

우리가 작성해야하는 로그 예시이다.

📗 v1

📄 V1 개발

@Getter
public class TraceId {

    private String id;
    private int level;

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

    // 외부에는 공개하지 않기 위해 private 생성자로 정의
    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;
    }
}

TraceId 객체를 정의하며 필요한 method들도 한번에 정의했다.

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

log의 상태 정보를 가지고 있을 TraceStatus class도 정의했다.

@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을 정의해보았다.

📄 테스트

public class HelloTraceV1Test {

    @Test
    void begin_end() {
        HelloTraceV1 trace = new HelloTraceV1();
        TraceStatus status = trace.begin("hello");
        trace.end(status);
    }
}

테스트 코드를 작성하고 결과를 봐보자.

다음 테스트를 진행하면 우리가 찍은 로그가 찍히며 시간을 계산해서 알려준다.

public class HelloTraceV1Test {

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

예외처리한 부분도 테스트해보자

발생한 에러와 에러가 발생하기까지 걸린 시간을 표시해준다.

📄 로그 추적기 적용하기

먼저 v0로 정의해두었던 Repository, Service, Controller를 모두 v1 패키지를 생성하여 복사해주자.

귀찮으면 안해도 된다.

그 후에 url도 v1으로 변경한 뒤

url로 요청하여도 잘 진행이 된다면 정상적으로 따라오고 있는 것이다.

@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; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}

Controller에 다음과 같이 로그를 찍도록 추가해준다.

이제 해당 url로 요청을 보내면 컨트롤러 자체에서도 로그를 찍어낼 수 있는 것을 확인할 수 있다.

예외가 발생했을 때 로그도 확인이 된다.

이제 Service와 Repository에 적용해보자.

@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("OrderService.orderItem()");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}

Service에 적용했고

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV1 {
    private final HelloTraceV1 trace;

    public void save(String itemId) {

        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepository.save()");

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

            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }

    }

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

Repository에 적용한 코드이다.

그럼 다음 로그가 나오는게 정상이다. 아직 레벨에 따라 적용시킨 적이 없기 때문에 지금 저 로그가 맞다.

📙 v2

📄 v2 개발

이전에 찍어낼 로그와 같이 적용하기 위해 위의 내용을 토대로 v2를 개발해보자.

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

v2에 추가된 beginSync() mehtod를 추가하여 작성해준다.

이렇게 V2를 만들어서 작성해주면 된다.

📄 테스트

public class HelloTraceV2Test {

    @Test
    void begin_end() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
        trace.end(status1);
        trace.end(status2);
    }

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

test 코드를 또 작성해서 확인해보자

테스트 결과가 이제 우리가 원하던 화살표가 나오며 에러가 났을 땐 x가 추가되도록 처리되어지고 있는 것을 확인할 수 있다.

📄 v2 적용하기

위에서 v1과 동일하게 v2로 repository, service, controller를 모두 복사해준다.

복사된 코드들을 controller, service, repository 순서로 수정해보자

@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; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}
@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.orderItem()");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}
@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.save()");

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

            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }

    }

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

그 후 로그를 확인하면 드디어 우리가 처음 만드려고 했던 로그를 확인할 수 있게 되었다.

👏 끝!

요구사항을 만족할 수 있게 프로그램을 작성했다. 하지만 이 프로그램의 문제는 하나의 요청의 TraceId값을 파라미터로 계속 넘겨야하는데 연관된 class를 모두 찾아서 모두 고쳐야한다는 문제점이 존재한다.

이러한 문제를 앞으로 해결할 수 있도록 계속해서 학습해보자!

profile
최준호
해당 주소로 이전하였습니다. 감사합니다. https://ililil9482.tistory.com
이전 포스트

Spring Boot version 별 릴리즈 노트 읽어보기

다음 포스트

Thread Local (feat. Singleton 동시성 문제)

post-custom-banner

0개의 댓글