스프링 코어2 - 악취 풍기는 로그 추적기 💩 🪰

로그 추적기를 서비스에 적용하기

사용자의 요청에 대한 로그 추적기를 만들어 보자.

만약 사용자가 주문 서비스를 사용했을 시에 아래 처럼 요청에 대한 로그들을 남기고 싶은 것이다.

요구사항을 간단히 정리하면 다음과 같다.

1. 모든 public 메서드의 호출과 응답 정보를 로그로 출력

2. 어플리케이션의 흐름을 변경하면 안됨 (로그를 남긴다고 해서 비즈니스 로직이 동작에 영향을 주면 안된다.)

3. 메서드 호출에 걸린 시간을 출력할 수 있어야 한다.

4. 정상 흐름과 예외 흐름을 구분하여야 한다.

먼저 프로젝는 start.spring.io에서 lombok과 Spring Web만을 추가한 가벼운 어플리케이션이다.

예시는 주문 서비스로 만들 것이기 때문에, OrderController, OrderService, OrderRepository들을 만들어 준다.

(뒤에 version0이라는 의미로 V0이 붙어있는데, 점점 발전 시키는 방향으로 예제를 수정해나갈 것이다.

OrderController

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

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

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

OrderService

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

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

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

OrderRepository

import org.springframework.stereotype.Repository;


@Repository
public class OrderRepositoryV0 {
    public void save(String itemId) {
        //저장 로직
        if (itemId.equals("ex")) throw new IllegalStateException("예외 발생!");
        //저장 로직을 수행하는데 1초가 걸린다고 가정
        sleep(1000);
    }

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

해당 서비스는 정말 단순하게 사용자가 itemId를 같이 담아서 요청하면 컨트롤러->서비스->리퍼지토리를 거쳐 DB에 저장되었다고 가정하고(Thread.sleep(1000)), 그 결과로 "ok" 문자열을 사용자에게 반환해준다.

로그 추적기 만들기

이제 로그 추적기를 만들어 보자.

먼저 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId와 TraceStatus다

TraceId : 로그 추적기에는 트랜잭션ID와 깊이 표현이 필요함

import lombok.Getter;
import java.util.UUID;

@Getter
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);//랜덤 UUID의 8자리만 사용
    }

    public TraceId createNextId(){
        //id는 그대로 level만 1증가시킨다.
        return new TraceId(id, level+1);
    }

    public TraceId createPrevious(){
        //id는 그대로 level은 1감소시킨다.
        return new TraceId(id, level - 1);
    }

    public boolean isFirstLevel(){
        return level == 0;
    }
}

요청에 대한 ID는 UUID를 사용하여 랜덤으로 만든다. (createId와 생성자)

createNExtId, createPreviousId : 남겨진 로그 예시에서 본 것처럼 각 level에 따라 표현되는 로그의 형태가 다르다. 이를 위한 메소드이다.

TraceStatus : 로그의 상태 정보를 나타냄

import lombok.AllArgsConstructor;
import lombok.Getter;

@Getter
@AllArgsConstructor
public class TraceStatus {
    private TraceId traceId;
    private Long startTimeMs;
    private String message;
}

TraceStatus는 TraceId를 가진다. 또한 startTimeMs는 응답에 걸리는 총 시간을 로그에 추가하기 위해 필요하다.

message에는 호출된 객체와 메소드명이 담길 것이다.

이제 TraceId와TraceStatus를 사용하여 실제 로그를 생성하고, 처리하는 클래스를 만들어보자.

HelloTraceV1

import hello.advanced.app.trace.TraceId;
import hello.advanced.app.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());
        }
    }

    // level 0 : ""
    // level 1 : "|-->"
    // level 2 : "|  |-->"
    // level 2 + 에외 : "|  |<X-"
    // level 1 + 에외 : "|<X-"
    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() : 로그를 시작해준다. message를 받아서 시작 로그를 출력해준다. 응답 결과로 현재 로그의 상태인 TraceStatus를 반환한다.

end() : 로그를 정상으로 종료해준다. 파라미터로 시작 로그의 상태(TraceStatus)를 전달 받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료시에도 시작할 때로 동일한 로그 메시지를 출력할 수 있다. 정상 흐름에서 호출한다.

exception() : 로그를 예외 상황으로 종료한다. TraceStatus, Exception 정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다. 이는 예외가 발생했을 때 호출한다.

complete() : end(), exception()의 요청 흐름을 한곳에서 편리하게 처리한다. 실행 시간을 측정하고 로그를 남긴다.

addSpace() : level에 따른 결과들을 출력한다.

이를 Test해보자

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

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

테스트 결과:

콘솔창 :

[14920dd6] hello
[14920dd6] hello time=0ms
[028a79dd] hello
[028a79dd] hello time=5ms ex=java.lang.IllegalStateException

각 로그들이 잘 출력되는 것을 확인하였다.

이제 Order서비스에 로그 추적기를 적용시켜보자.

OrderController

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.hello_trace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.apache.el.stream.Optional;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RequiredArgsConstructor
@RestController
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;//예외를 반드시 던져줘야 한다.
        }
    }
}

OrderService

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.hello_trace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@RequiredArgsConstructor
@Service
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;//예외를 반드시 던져줘야 한다.
        }
    }
}

OrderRepository

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.hello_trace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

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

    public void save(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderService.orderItem()");
            // --- 저장 로직 ---
            if (itemId.equals("ex")) throw new IllegalStateException("예외 발생!");
            //저장 로직을 수행하는데 1초가 걸린다고 가정
            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();
        }
    }
}

이전의 주문 서비스 Controller, Service, Repository에 로그 추적 기능을 추가하였다.

이를 실행해보면 다음과 같다.

정상 로직 요청:

로그 출력 결과는 아래와 같다.

예외 발생 요청:

로그 출력 결과는 아래와 같다.

하지만 현재의 코드에는 많은 문제점들이 많다.

1. 메서드 호출의 깊이가 표현되지 않음

2. HTTP요청에 따른 트랜잭션ID가 적용되지 않음. (Controller, Service, Repository에서 TraceStatus들을 각각 만든다.)

== > 로그에 대한 Context(문맥)이 유지되지 않는다.

하여 이와 같은 문제를 해결하기 위해 적용할 수 있는 가장 간단한 해결법은 파라미터 동기화이다.

파라미터 동기화를 적용하여 위 문제점들을 해결해보자.

파라미터 동기화로 해결하기

HelloTraceV1에서 이전의 TraceStatus를 넘겨 받을 수 있는 메서드인 beginSync를 추가한 HelloTraceV2를 보자.

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

@Slf4j
@Component
public class HelloTraceV2 {
    // ...이전과 동일...
    
    //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);
    }

    // ...이전과 동일...
}

beginSync메소드는 이전의 객체에서 받은 TraceId를 그대로 사용하고, beforeTraceId.createNextId()를 호출하여 level을 한 단계 올려주는 것 외에는 모두 같은 로직이다.

이를 테스트 해보자.

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


class HelloTraceV2Test {

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

    @Test
    void begin_exception() {
        HelloTraceV2 trace = new HelloTraceV2();
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.beginSync(status1.getTraceId(),"hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

테스트 결과:

콘솔창:

[4da124a7] hello
[4da124a7] |-->hello2
[4da124a7] |<--hello2 time=0ms
[4da124a7] hello time=0ms
[11b12eae] hello
[11b12eae] |-->hello2
[11b12eae] |<X-hello2 time=1ms ex=java.lang.IllegalStateException
[11b12eae] hello time=5ms ex=java.lang.IllegalStateException

level이 잘 적용되어 나오는 것을 볼 수 있다.

이제 HelloTraceV2를 주문 서비스에 적용해보자.

OrderController는 이제 OerderService의 orderItem메서드 호출 시에 TraceId를 넘겨줘야 한다.

마찬자기로 OrderService 역시 OrderRepositoty의 save메서드를 호출 할 때에 TraceId를 넘겨준다.

또한 OrderService와 OrderRepositoty는 begin대신 beginSync메서드를 사용하여 TraceStatus객체를 얻는다.

OrderController

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.hello_trace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RequiredArgsConstructor
@RestController
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);/* OrderService에 TraceID를 넘겨준다. */
            trace.end(status);
            return "ok";

        } catch (Exception e) {
            trace.exception(status, e);
            throw e;//예외를 반드시 던져줘야 한다.
        }
    }
}

OrderService

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

@RequiredArgsConstructor
@Service
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()");/* beginSync 사용 */
            orderRepository.save(status.getTraceId(), itemId);/* OrderRepository에 TraceID를 넘겨준다. */
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;//예외를 반드시 던져줘야 한다.
        }
    }
}

OrderRepository

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

@RequiredArgsConstructor
@Repository
public class OrderRepositoryV2 {
    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {
        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderService.orderItem()");/* beginSync 사용 */
            // --- 저장 로직 ---
            if (itemId.equals("ex")) throw new IllegalStateException("예외 발생!");
            //저장 로직을 수행하는데 1초가 걸린다고 가정
            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();
        }
    }
}

정상 로직 요청:

로그 출력 결과는 아래와 같다.

에러 발생 요청:

로그 출력 결과는 아래와 같다.

마무리

모든 요구사항들은 만족되었지만 현재의 코드는 상당한 악취를 풍기는 코드이다.

HTTP 요청을 구분하고 level을 알기 위해 TraceId를 넘겨줘야한다. 이는 많은 문제점들을 초래한다.

문제 ::

===> 1. 기존의 코드가 양이 상당히 많다면?

현재는 주문 서비스의 controller, service, repository 세 단계만을 거치치만 order, customer, payment, product 등등 수많은 서비스의 코드들(메소드들)을 바꾸어야 한다. 만약 각 클래스들이 인터페이스에 의존하고 있었다면 인터페이스까지 바꾸어야 한다.

===> 2. 로그를 시작할 때는 begin(), 처음이 아닐 때는 beginSync()를 호출한다.

현재는 컨트롤러에서만 begin을 호출하지만, 만약 다른 곳에서 서비스를 처음 시작한다면 이는 도대체 어디서는 begin(), 또 어디서는 beginSync()이어야 하는지 굉장히 헷갈린다.

정리하면 즉 위의 코드는 확장에는 닫혀있고 변경에는 열려있는 OCP원칙을 매우 위배하고 있는 코드들인 것이다. 요 악취 풍기는 코드를 앞으로 수정해보자.

저작자표시

'Spring > spring AOP' 카테고리의 다른 글

스프링 코어2 - 프록시 학습을 위한 프로젝트 만들기 (0)	2022.01.06
스프링 코어2 - 템플릿 콜백 패턴 (0)	2022.01.05
스프링 코어2 -전략 패턴 (0)	2022.01.05
스프링 코어2 - 템플릿 메서드 패턴(로그 추적기에 패턴 도입) (0)	2022.01.04
스프링 코어2 - 로그추적기(feat.Thread Local) (0)	2022.01.02

어제보다 오늘 더

스프링 코어2 - 악취 풍기는 로그 추적기 💩 🪰

로그 추적기를 서비스에 적용하기

로그 추적기 만들기

마무리

'Spring > spring AOP' 카테고리의 다른 글

티스토리툴바

스프링 코어2 - 악취 풍기는 로그 추적기 💩 🪰

로그 추적기를 서비스에 적용하기

로그 추적기 만들기

마무리

'Spring > spring AOP' 카테고리의 다른 글

관련글

티스토리툴바