로그 추적기로 알아보는 디자인패턴

 

스프링 핵심 원리 - 고급편 - 인프런 | 강의

 

서비스를 확장하고 지속가능한 운영을 하기 위해서는 아래와 같은 정보가 필요하다.

• 어느 시점에서 성능상 병목이 발생하고 있는가?
• 어떤 장애가 발생했으며, 고객이 가장 많이 겪는 장애는 무엇인가?
• 가장 트래픽이 많은 서비스 / 잘 사용되지 않는 서비스 기능은 무엇인가?

이러한 로그들을 어떻게 남기고 관리해야하는지 차근차근 알아보자.

물론 최근에는 모니터링 도구(ELK등)을 쓰면 간단하지만, 이런 도구가 없는 과거에는 어떻게 로그를 남겼는지 배워보자.

 

 

💭 로그 기능을 추가해보자

📌 어떤 기능이 필요할까

정상흐름과, 오류가 발생한 예외흐름을 구분해서 볼 수 있어야 한다.
아래와 같이 서비스에 의미있는 모든 로그를 남겨야한다.

• 공개된(Public) 메서드의 호출과 응답정보
• 메서드 호출 및 처리에 걸린시간
• 각 HTTP 요청에 [고유한 트랜잭션 ID]를 붙여서 구분하기 좋게 기록한다.

위의 요청사항을 만족한 로그 기록.

 

 

📌 하나씩 만들어보자.

그냥 서비스 로직 위아래로 trace.begin() ~ trace.end() 해서 기록하면 되는거 아닐까?

로그를 추가, 유지보수하는건 골치아픈 일이다. 왜 그런지 코드를 통해 알아보자.

 

1. 로그를 담당하는 객체를 만든다.

Trace, TraceId 등의 객체를 만들고, 로그를 남길 메서드 begin() end() 를 만든다.

@Slf4j
@Component
public class TraceV1 {

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

 

 

2. 이를 사용해서 로그를 남긴다. 아직까진 할만한다.

private final TraceV1 trace; // 스프링 빈으로 등록

@GetMapping("/request")
public String request(String itemId) {
    TraceStatus status = trace.begin("OrderController.request()"); // 로그 시작
    orderService.orderItem(itemId);
    trace.end(status); // 로그 종료

    return "ok";
}

 

 

3. 이제 예외와 정상 흐름을 구분해서 로그를 남기도록 만든다. 슬슬 복잡해진다

로그를 담당하는 객체가 직접 예외처리를 하거나, 서비스나 비즈니스로직에 영향을 주면 안된다.

@GetMapping("/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;// 로그는 어플리케이션 흐름을 수정하지 않는다. 예외는 다시 던진다.
    }
}

 

 

4. 각 메서드별로 TraceId를 지정한다. 어떤 메서드가 호출되었는지, 호출 스택(Level)을 로그에 남긴다.

이를 위해서는 Controller 뿐 아니라 Service, Repository 까지 아래와 같은 로깅 로직을 작성해주어야한다.

이렇게 [트랜잭션 ID]를 만들어 메서드의 호출흐름, 깊이를 로그에 기록한다.

@Service
public class OrderService {

    private final OrderRepository orderRepository;
    private final Trace trace;

    public void orderItem(TraceId traceId, String itemId) {
        TraceStatus status = null;
        try {
            // 메서드 깊이를 기록하기위해, beginSync() 메서드를 추가한다. 기존 로깅에 추가
            status = trace.beginSync(traceId, "OrderService.orderItem()");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

@Repository
public class OrderRepository {

    private final Trace trace;

    public void save(TraceId traceId, String itemId) {
        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderRepository.save()");
            /* ...저장 로직... */
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

 

 

5. HTTP 요청단위로 각 로그를 구분한다. 같은 요청이면 같은 [Trace ID]를 가지도록 동기화한다.

이를 위해서 서비스에서 traceId를 직접 지정하는게 아니라, 아래와 같이 로그 객체가 가지고 있도록 리팩토링한다.

public void orderItem(String itemId) {
    TraceStatus status = null;
    try {
        // 기존 코드 status = trace.beginSync(traceId, "OrderService.orderItem()");
    	status = trace.begin("OrderService.orderItem()");
    }
}

• 같은 로깅 객체를 사용한다면 syncTraceId()를 통해 [Trace ID]를 동기화하고 메서드 호출레벨을 +1 한다.
• 로깅이 끝날 때 releaseTraceId()를 통해 [Trace ID]를 동기화하고 메서드 호출레벨 -1 한다.

@Component
public class FieldLogTrace {

    private TraceId traceIdHolder; // traceId를 객체가 들고있도록 변경
    
    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.createNextId(); // 호출레벨 +1
        }
    }
    
    private void releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null; //destroy
        } else {
            traceIdHolder = traceIdHolder.createPreviousId(); // 호출레벨 -1
        }
    }
    ...
}

@Component
public class FieldLogTrace {
    ...
    public TraceStatus begin(String message) {
        syncTraceId(); // Trace Id 동기화
        
        TraceId traceId = traceIdHolder;
        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());
        }

        releaseTraceId();
    }
}

 

 

🧨 FieldLogTrace는 동시성문제를 발생시킨다.

스프링 컨테이너를 공부했다면 알겠지만, 기본적으로 @Component는 싱글톤 객체로 등록된다.

즉 앱 실행시점에 한번 만들어놓고 재사용한다. 여러 트랜잭션에서 같은 값을 수정하기때문에 로그가 이상하게 찍힌다.

실제 운영 로그는 [Trace ID]를 모두가 사용하고, 로그가 개판으로 찍힌다.

가장 심각한 문제는, 개발할 때에는 이러한 동시성 문제를 인지하기 어렵다.  간단한 테스트 코드로는 발견하기 어렵다.

/* 해당 테스트는 동시성 문제를 찾아주지 않는다. 정상적으로 동작하고, 테스트에 성공한다.*/
public class FieldLogTraceTest {

    FieldLogTrace trace = new FieldLogTrace();

    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("hello1");
        trace.end(status2);
    }

    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("hello1");
        trace.exception(status2, new IllegalStateException());
    }
}

또한 운영도중 알았다고 해도, 어디서 문제가 발생했는지 모르기에 모든 코드를 다 뒤져보며 디버깅 해야한다. 끔찍하다.

 

 

6. 동시성 문제해결 방법 - ThreadLocal 사용

동시성 문제를 해결하기위해 자바의 java.lang.ThreadLocal 객체를 사용하여 문제를 해결해보자.|
물론 싱글톤 빈을 쓰지않고 매번 새로운 객체를 만들거나, 아예 상태 값(Thread-Id)을 필드가 아닌 메서드 인자로 주고 받는 방법도 있다. 하지만 그렇게하면 성능도 구려지고 유지보수하기 정말 어려워진다.

자바의 ThreadLocal 객체는 [해당 스레드만 사용가능한 메모리]를 만들어 제공해준다.

사용법은 간단하다. ThreadLocal<객체>로 감싸고, 컬렉션처럼 넣고 꺼내 쓰면 된다.

public class ThreadLocalService {

    private ThreadLocal<String> nameStore = new ThreadLocal<>();
    // ThreadLocal.set("~")
    // ThreadLocal.get()
    // ThreadLocal.remove()
    
    public String logic(String name) {
        nameStore.set(name);
        return nameStore.get();
    }
}

 

 

🧨 WAS(톰캣 등)에서의 ThreadLocal 사용시 주의사항

ThreadLocal 사용 이후 스레드 종료이전에 반드시 .remove()로 할당 해제해줘야한다.

private void releaseTraceId() {
    TraceId traceId = traceIdHolder.get();
    if (traceId.isFirstLevel()) {
        traceIdHolder.remove(); //destroy
    } else {
        traceIdHolder.set(traceId.createPreviousId());
    }

그 이유는 스레드 풀을 사용하기 때문이다. 스레드는 제거되지 않고 재사용되기에 메모리 누수가 발생하기 쉽다.

메모리 누수만 발생하면 다행인데, 기존의 ThreadLocal을 다른 사용자가 재사용하는 끔찍한 보안 문제도 같이 발생한다.

물론 스레드 풀을 사용하지 않더라도, remove()를 통해 해제시켜주는게 좋다. 메모리 누수 방지용

 

 

📌 모든 요구사항을 만족했다. 이제 끝난걸까?

로그는 오류 없이 정상적으로 기록된다. 하지만 로그 때문에 코드가 엄청 더러워지고, 아래와 같은 문제점이 생겼다.

• 로그 때문에 정상 로직이 무엇인지 찾기 어려워진다. 유지보수가 너무 어렵다
• 로그를 사용하기 어렵다. 앱 기능을 개발할 때 로그 메서드 (begin, exception, beginSync)를 구분지어 호출해야한다.
• 사이드이펙트. 모든 서비스 객체에 Log Trace 객체에 대한 의존성이 생긴다.
• Log Trace 객체를 수정하면, 서비스 객체에 변경이 전파된다. 앱 흐름에 영향을 끼친다.
  로그 기능은 잘 변하지않지만, 앱 로직은 언제든지 변할 수 있다. 각 코드가 서로에게 영향을 끼쳐서는 안된다.

 

로그는 말 그대로 없어도 되는 '부가기능'이다. 앱, 비즈니스 로직과 같은 핵심기능에 영향을 끼쳐서는 안된다.

앱 로직에 영향을 주지않고, 어떻게 서비스에 관련된 로그를 남길 수 있을까? 그런게 가능한가?

 

 

---

💭 문제해결 - 디자인 패턴

결론부터 말하자면, 가능하도록 설계를 잘 하면 된다. 자주 사용하는 설계 방법을 모아둔 것을 디자인패턴이라 한다.

 

설계에는 언제나 사용할 수 있는 정답이 없다. 상황에 따라 더 나은 방법을 선택해야한다.

위에서 로그기능을 만들 때 생긴 문제를 해결할 수 있는 다양한 디자인 패턴들에 대해 알아보자.

🧨디자인 패턴을 생각없이 무작정 따라하지 말자. 왜 이렇게 사용하는지에 대한 '이유'가 더 중요하다.

 

📌 템플릿 메서드 패턴

변화하지 않는 공통된 골격(틀)을 재사용 가능한 템플릿, 즉 [추상 클래스]로 뽑아내는 방법이다.

세부동작(알고리즘)은 상속을 받아 정의한다.

서비스에 로그를 추가할 때, 우리는 아래와 같은 코드를 반복적으로 작성했다.

public void log() {
    long startTime = System.currentTimeMillis();
    
    /* ...서비스 기능... */
    
    long endTime = System.currentTimeMillis();
    long resultTime = endTime - startTime;
    log.info("로그 resultTime={}", resultTime);
}

 

이를 템플릿 메서드를 적용시켜 추상화시키면 된다. 이제 서비스 로직에는 더 이상 로그를 신경쓰지 않아도 된다. 

public abstract class AbstractTemplate {

    public void execute() {
        long startTime = System.currentTimeMillis();
        //비즈니스 로직 실행
        service();
        //비즈니스 로직 종료
        long endTime = System.currentTimeMillis();
        long resultTime = endTime - startTime;
        log.info("resultTime={}", resultTime);
    }

    protected abstract void service();
}

public class OrderService extends AbstractTemplate {
    @Override
    protected void service() {
        /*... 비즈니스 로직 ...*/
    }
}

 

아래와 같이 다형성을 활용하면 쉽게 사용할 수 있다.
로그를 수정해도 서비스 로직을 변경할 필요가 없다. 두 부분이 깔끔하게 분리되었다.

AbstractTemplate template1 = new OrderService();
AbstractTemplate template2 = new ItemService();

template1.service();
template2.service();

 

 

단점1. 매번 새로운 상속해서 새롭게 작성하기 번거롭다.

추상화한건 좋았으나, 매번 중복되는 템플릿 클래스를 작성해야하는 번거로움이 있다.

이는 익명클래스나 Java8의 함수형 인터페이스(람다)를 활용하면 쉽게 해결할 수 있다.

AbstractTemplate itemRepository = new AbstractTemplate() {
    @Override
    protected void service() {
        log.info("비즈니스 로직1 실행");
    }
};
itemRepository.service();


// 객체로 전달할 때에는 이렇게 함수형 인터페이스(람다)를 활용할 수 있다.
// new ItemService( ItemRepository repository );
var ItemService = new ItemSerivce( () -> log.info("비즈니스 로직1 실행") );

참고로 익명이나 람다로 생성된 클래스는 AbstractTemplate$1, AbstractTemplate$2 같은 이름으로 JVM에 생성된다.

 

 

위 템플릿을 제네릭과 인터페이스로 조금 다듬으면, 아래와 같이 편하게 사용할 수 있다.

@RestController
public class OrderController {

    private final OrderService orderService;
    private final TraceTemplate template;

    public OrderController(OrderService orderService, LogTrace trace) {
        this.orderService = orderService;
        this.template = new TraceTemplate(trace);
    }

    @GetMapping("/request")
    public String request(String itemId) {
        return template.execute("OrderController.request()", () -> {
            orderService.orderItem(itemId);
            return "ok";
        });
    }
}

 

여기에 사용된 코드는 아래와 같다.

public interface TraceService<T> { // 함수형 인터페이스
    T service();
}

public interface LogTrace { // 로그 구현체를 변경할 수 있게, 인터페이스로 사용한다. DIP

    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

public class TraceTemplate {
    private final LogTrace trace;

    public <T> T execute(String message, TraceService<T> callback) {
        TraceStatus status = null;
        try {
            status = trace.begin(message);
            
            /* 서비스 로직 시작 */
            T result = callback.service();
            /* 서비스 로직 종료 */
            
            trace.end(status);
            return result;
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

 

 

단점2. 상속관계로 인해 의존성이 생긴다.

템플릿 메서드에서는 상속을 통해 클래스의 골격(Template)을 만든다.

자식클래스(Log)는 부모클래스의 기능을 전혀 사용하지않는데, 설계를 위해서 부모클래스에 의존성을 만든다.

상속 구조를 사용하기 때문에 위 예제처럼 TraceService<T> 같은 추가적인 클래스도 필요하다는 단점도 있다.

 

이 문제를 해결하는 방법은 간단하다. 상속을 사용하지 않고 필드로 받아서 만들면 된다. 의존성을 제거하자

➡ 전략패턴 (Strategy Pattern)

 

 

📌 전략패턴

템플릿 메서드 패턴은, 변하지 않는 골격을 부모클래스(Template)로 뽑아내고, 상속을 통해 세부동작을 구현했다.

전략 패턴은 상속이 아닌 필드를 사용해 인터페이스를 통한 위임으로 세부동작을 구현한다.

public interface Strategy {
    void call();
}

@Test
void test() {
    Strategy myStrategy = new StrategyLogic();
    Context context1 = new Context(myStrategy);
    context1.execute();

    // 함수형인터페이스(람다) 활용
    Context context2 = new Context(() -> log.info("비즈니스 로직1 실행"));
    context2.execute();
}

@Slf4j
public class Context {

    private Strategy strategy;

    public Context(Strategy strategy) {
        this.strategy = strategy;
    }

    public void execute() {
        long startTime = System.currentTimeMillis();
        
        //비즈니스 로직 실행
        strategy.call(); // 위임
        //비즈니스 로직 종료
        
        long endTime = System.currentTimeMillis();
        long resultTime = endTime - startTime;
        log.info("로그 resultTime={}", resultTime);
    }
}

 

템플릿 메서드와 달리, 틀(Strategy)과 구현체 사이에 아무런 의존성이 없다.

그래서 로그 기능이 아니더라도, 필요한 다른 기능을 적절하게 구현할 수 있다.

 

 

단점1. 전략(Strategy)을 설정한 후, 나중에 변경하기 어렵다.

물론 내부에 setStrategy(...)를 사용하는 방법도 있지만, 싱글톤 객체에서 상태 값을 변경할 수 있는 Setter를 두는건 매우 위험하다. 차라리 객체를 새롭게 만드는게 나을 수도 있다. 멀티스레드 동시성 문제나 버그가 발생하기 쉽다. 

 

한 객체(Service)에서 상황에 따라 다른 전략(알고리즘)을 적용시키고 싶다면, 아래와 같이 메서드로 받으면 된다.
다만 실행할 때 마다 전략을 지정해주는게 번거롭다는 단점이 있다. 상황에 따라 적절하게 사용하자.

@Test
void test() {
    ContextV2 context = new ContextV2(); // 생성 시점에는 비워둔다.

    // 사용하는 시점에 적절한 Strategy 구현체를 전달한다.
    context.execute(() -> log.info("비즈니스 로직1 실행"));
    context.execute(() -> log.info("비즈니스 로직2 실행"));
    
    // 고유한 상태 값(필드)가 없다면, 매번 객체를 만들지 않고 재사용할 수도 있다.
    context.execute(myStrategy());
}

 

 

📌 템플릿 콜백함수(callback function)

참고로 함수를 인자(파라메타)로 넘겨주는걸 callback 함수(call-after function)라고 부른다.

당장 실행하지 않고, 함수를 인자로 받아 필요한 시점에 실행한다는 의미.

 

콜백 함수는 디자인 패턴은 아니고, 함수형 프로그래밍에서 많이 사용하는 기법이다.

방금 언급한 [메서드를 이용한 전략패턴]과 비슷하다. 다른 점은 콜백함수를 사용한다는거 정도

자바는 메서드가 일급시민 (인자로 전달, 리턴 가능)한 대상이 아니기에 콜백함수 구현이 불가능했다.

이를 해결하기위해 JDK8부터는 함수형 인터페이스와 함수를 쉽게 전달하게 해주는 Function-Class API를 제공해준다.

참고로 스프링의 JdbcTemplate, RestTemplate, TransactionTemplate, RedisTemplate 등은 콜백 패턴을 이용한다.

 

아래 예제에서는 Runnable이라는 함수형 인터페이스를 사용했으나, 필요하다면 인터페이스를 따로 만들어도 된다.

예) public void execute(MyCallback callback)

public class TimeLogTemplate {

    public void execute(Runnable callback) {
        long startTime = System.currentTimeMillis();

        //비즈니스 로직 실행
        callback.run(); //위임
        //비즈니스 로직 종료

        long endTime = System.currentTimeMillis();
        long resultTime = endTime - startTime;
        log.info("resultTime={}", resultTime);
    }
}

@Test
void callback() {
    TimeLogTemplate template = new TimeLogTemplate();
    template.execute(() -> log.info("비즈니스 로직1 실행"));
    template.execute(() -> log.info("비즈니스 로직2 실행"));
}

 

 

📌 해결할 수 없는 문제점

아무리 추상화를 하고 의존성을 끊어낸다고 한들, Template 자체를 없앨 수는 없다.

사용법은 간단해졌지만 결국 각 서비스에서 Template 인터페이스는 호출해줘야한다.

 

 

🤔 스프링은 되던데요?

맞다. 스프링은 다이나믹 프록시를 활용한 AOP를 통해 프록시 패턴과 데코레이터 패턴을 구현하여 해결했다.

사실 데코레이터 패턴과 프록시 패턴은 거의 비슷하다. 디자인패턴을 '모양'이 아닌 '의도'에 따라 구분하자. 

• 프록시 패턴: 접근제어가 목적
• 데코레이터 패턴: 새로운 기능 추가가 목적

2021.08.17 - [🌱Backend/Spring Core] - 자바 AOP의 모든 것(Spring AOP & AspectJ)

자바 AOP의 모든 것(Spring AOP & AspectJ)