스프링 핵심원리( 심화 ) - 로그 추적기와 동시성( 로그 추적기 개발 )

로그 추적기의 필요성

서비스가 점차 거대해지고 사용되는 소스 코드와 클래스가 수 십만 라인에 수 백개 이상이 존재한다면, 

점차적으로 운영 환경에서의 모니터링과 운영이 중요해진다.

 

특히 성능적인 이슈와 관련하여 병목과 같은 현상에서 병목의 발생 지점을 파악하거나 예외 발생 지점 등을 파악하는 것이 필요해진다.

 

그리고 이러한 지점들을 로그로 남기는 것이 어플리케이션의 실행과 운영에서 상태 파악과 많은 문제들에 대한 힌트를 제공할 수 있기에 중요한 부분이다. 

 

따라서 로그 추적기를 개발하면서 다음과 같은 요구 사항들을 구현해보자.

요구사항

✅ 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력

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

✅ 메서드 호출에 걸린 시간 정상 흐름과 예외 흐름 구분
  예외 발생시 예외 정보가 남아야 함

✅ 메서드 호출의 깊이 표현

✅ HTTP 요청을 구분
  HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
  트랜잭션 ID (DB 트랜잭션X), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트랜잭션이 라 함

 

이에 대한 예시는 아래와 같은 형식이다. 

정상 요청
[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: 예외 발생!

 

이를 위한 개발을 진행해보자.

 

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

애플리케이션의 모든 로직에 로그를 남길 수도 있지만, 트랜잭션ID (고유 ID)와 더불어 로직의 깊이를 표현하여 보다 파악하기 쉬운 로그를 남기고 정보를 전달할 것이기에 이를 위한 클래스가 필요하다.

 

TraceId 클래스

import java.util.UUID;

public class TraceId {

    private String traceId;
    private int level;
    
    public TraceId() {
        this.traceId = createId();
        this.level = 0;
    }

    private TraceId(String id, int level) {
        this.traceId = id;
        this.level = level;
    }

    private String createId() {
        return UUID.randomUUID().toString().substring(0, 8);
    }

    public TraceId createNextId () {
        return new TraceId(this.traceId, this.level + 1);
    }

    public TraceId createPreviousId () {
        return new TraceId(this.traceId, this.level - 1);
    }

    public boolean isRoot() {
        return this.level == 0;
    }

    public String getTraceId() {
        return traceId;
    }

    public int getLevel() {
        return level;
    }
}

 

TraceId 클래스는 각 고유 식별자에 해당하는 부분과 깊이를 표현하는 level 필드를 통해 각 부분이 아래와 같이 사용된다.

[796bccd9] OrderController.request() //트랜잭션ID:796bccd9, level:0
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID:796bccd9, level:1
[796bccd9] | |-->OrderRepository.save()//트랜잭션ID:796bccd9, level:2

 

메소드 설명

그리고 각 메소드가 의미하는 바는 다음과 같다.

 

createId()

TraceId 를 처음 생성하면 createId() 를 사용해서 UUID를 만들어낸다.

 

createNextId() , new TraceId(id, level + 1)

다음 TraceId 를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다.
대신에 깊이가 하나 증가한다.

[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID가 같다. 깊이는 하나 증가한다.

createNextId() 를 사용해서 현재 TraceId 를 기반으로 다음 TraceId 를 만들면 id 는 기존과 같고, level 은 하나 증가한다.

 

createPreviousId()

createNextId() 의 반대 역할을 한다.
id 는 기존과 같고, level 은 하나 감소한다.

 

isFirstLevel()

첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드

 

이처럼, TraceId 클래스는 로그 식별자를 가진 하나의 객체를 의미한다.

이제 각 식별자의 상태 정보를 나타내는 클래스를 만들어보자.

 

TraceStatus 클래스

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 Long getStartTimeMs() {
		 return startTimeMs;
	 }
	 
	 public String getMessage() {
		 return message;
	 }
	 
	 public TraceId getTraceId() {
		 return traceId;
	 }
 }

 

구현하려는 로그의 형태는 메세지와 실행 시간이 적혀있다.

[796bccd9] OrderController.request() //로그 시작
[796bccd9] OrderController.request() time=1016ms //로그 종료

즉, TraceStatus 클래스는 상태를 가진 TraceId와 더불어 메세지와 실행 시간 등의 상태 정보를 가지고 활용하기 위한 객체이다.

 

여기까지 로그의 정보를 담는 객체를 만들었고,

TraceId , TraceStatus 를 사용해서 실제 로그를 생성하고, 처리하는 기능을 개발해보자

@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.getTraceId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    public void end(TraceStatus status) {
        complate(status,null);

    }

    public void exception(TraceStatus status, Exception e) {
        complate(status, e);
    }

    private void complate(TraceStatus status, Exception e) {

        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTime();
        TraceId traceId = status.getTraceId();

        if (e == null) {
            log.info("[{}] {}{} time={}ms", traceId.getTraceId(),
                    addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
                    resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getTraceId(),
                    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();
    }
}

 

실질적으로 로그를 시작하고 종료함에 정보를 출력해주는 기능을 제공하는 것은 이 클래스가 수행한다.

 

메소드 설명

위의 객체에서 제공하는 기능( 메서드 )은 크게 다음의 3가지이다.

- begin()
- end()
- exception()

 

각 메서드가 의미하는 바를 파악해보자면 아래와 같다.

TraceStatus begin(String message)

로그를 시작한다.
로그 메시지를 파라미터로 받아서 시작 로그를 출력한다.
응답 결과로 현재 로그의 상태인 TraceStatus 를 반환한다.

 

void end(TraceStatus status)

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

 

void exception(TraceStatus status, Exception e)

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

 

private 메서드

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

 

String addSpace(String prefix, int level)

다음과 같은 결과를 출력한다.

prefix: -->
level 0: ``
level 1: |-->
level 2: | |-->

prefix: <--
level 0: ``
level 1: |<--
level 2: | |<--

prefix: <X-
level 0: ``
level 1: |<X-
level 2: | |<X-

 

그리고 이를 다음과 같이 로직에 붙여서 사용해보겠다.

 

Controller

적용 전(Controller)

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderserviceV1 orderservice;
    private final HelloTraceV1 helloTraceV1;

    @GetMapping("/v1/request")
    public String request(String item) {
        
        orderservice.OrderItem(item);

        return "ok";
    }
}

 

적용 후

@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {

    private final OrderserviceV1 orderservice;
    private final HelloTraceV1 helloTraceV1;

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

        TraceStatus status = null;

        try{
            status = helloTraceV1.begin("OrderControllerV1.request()");
            orderservice.OrderItem(item);
            helloTraceV1.end(status);
        } catch (Exception e) {

            helloTraceV1.exception(status, e);
            throw e; // 예외를 꼭 다시 던져주어야 한다.
        }

        return "ok";
    }
}

 

Service

적용 전(Service)

@Service
@RequiredArgsConstructor
public class OrderserviceV1 {

    private final OrderRepoV1 orderRepo;
    
    public void OrderItem(String item) {
        orderRepo.save(item);
    }
}

 

적용 후

@Service
@RequiredArgsConstructor
public class OrderserviceV1 {

    private final OrderRepoV1 orderRepo;
    private final HelloTraceV1 helloTraceV1;

    public void OrderItem(String item) {

        TraceStatus status = null;

        try{
            status = helloTraceV1.begin("OrderServiceV1.OrderItem()");
            orderRepo.save(item);
            helloTraceV1.end(status);
        } catch (Exception e) {
            helloTraceV1.exception(status, e);
            throw e;
        }
    }
}

 

Repository

적용 전(Repository)

@Repository
@RequiredArgsConstructor
public class OrderRepoV1 {

    public void save(String itemId) {
        if(itemId.equals("ex")) {
            throw new IllegalArgumentException("예외 발생");
        }

        sleep(1000);
    }


    private void sleep (long millis) {

        try{
            Thread.sleep(millis);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

적용 후

@Repository
@RequiredArgsConstructor
public class OrderRepoV1 {

    private final HelloTraceV1 helloTraceV1;

    public void save(String itemId) {

        TraceStatus status = null;

        try {
            status = helloTraceV1.begin("OrderRepoV1.save()");

            if(itemId.equals("ex")) {
                throw new IllegalArgumentException("예외 발생");
            }
            sleep(1000);
            helloTraceV1.end(status);

        } catch (Exception e) {
            helloTraceV1.exception(status, e);
            throw e;
        }

    }

    private void sleep (long millis) {

        try{
            Thread.sleep(millis);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

이제 변경한 로직으로 실행하면 다음과 같은 로그가 생성됨을 확인할 수 있다.

 

정상 흐름

 

예외 흐름

 

지금까지 만든 로그 추적기의 실행 결과를 보면,

위에서 제시한 로그와 달리 아직 로그의 깊이를 나타내거나, 로그 ID의 일관성을 보장하지 않고 있다.

 

각 Controller - Service - Repository 의 계층들에 고유 ID가 별도로 부여된 상태이다.

이는 아래와 같은 흐름을 따라서 각 로그가 생성되는 것이다.

 

 

따라서

요구 사항 중 메서드 호출의 깊이를 표현하고 HTTP 요청을 구분하는 두 가지 과제가 남았다.

요구사항

✅ 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력

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

✅ 메서드 호출에 걸린 시간 정상 흐름과 예외 흐름 구분
  예외 발생시 예외 정보가 남아야 함

☑️ 메서드 호출의 깊이 표현

☑️ HTTP 요청을 구분
  HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
  트랜잭션 ID (DB 트랜잭션X), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트랜잭션이 라 함

 

이것들은 단독적인 기능 수행으로는 수행할 수 없으며, 직전 로그의 깊이나 고유 ID값이 무엇인지 알고 전달하는 방식이어야 가능하다.

즉, Context 정보가 필요한 것이다.

 

 

로그 추적기 v2

이를 위해서 로그 추적기 개발에 기능을 추가해보겠다.

가장 단순하게 고유ID와 메서드 호출의 깊이를 표현하기 위해서 각 로그를 사용함에 파리미터로 값을 넘겨주는 것이다.

 

이 기능을 추가한 로그 추적기 객체는 아래와 같다.

@Component
@Slf4j
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.getTraceId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

		// 추가된 메서드 
    public TraceStatus beginSync(TraceId beforeTraceId  ,String message) {
//        TraceId traceId = new TraceId();

        TraceId nextId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();

        log.info("[{}] {}{}", nextId.getTraceId(), 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.getStartTime();
        TraceId traceId = status.getTraceId();

        if (e == null) {
            log.info("[{}] {}{} time={}ms", traceId.getTraceId(),
                    addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(),
                    resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getTraceId(),
                    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();
    }

}

beginSync 메서드가 추가되었고, 해당 기능을 요약하자면

TraceId 객체를 받아서 createNextId()를 호출하고 로그를 생성하는 것이다.

 

따라서, 처음에는 begin()을 사용하고, 이후에는 beginSync()를 사용하여 깊이의 증감 및 TraceId를 표현하면 된다.

이제 위의 로직을 적용해서 코드에 적용하고 로그를 생성해보자.

 

@RestController
@RequiredArgsConstructor
@Slf4j
public class OrderControllerV2 {

    private final OrderserviceV2 orderservice;
    private final HelloTraceV2 helloTraceV1;

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

        TraceStatus status = null;

        try{
            status = helloTraceV1.begin("OrderControllerV2.request()");
            orderservice.OrderItem(status.getTraceId(),item); // 변경된 부분
            helloTraceV1.end(status);
            return "ok";
        } catch (Exception e) {

            helloTraceV1.exception(status, e);
            throw e; // 예외를 꼭 다시 던져주어야 한다.
        }
    }
}

 

@Repository
@RequiredArgsConstructor
public class OrderRepoV2 {

    private final HelloTraceV2 helloTraceV1;

    public void save(TraceId traceId, String itemId) {

        TraceStatus status = null;

        try {
            status = helloTraceV1.beginSync(traceId,"OrderRepoV2.save()"); 
            // 변경된 부분

            if(itemId.equals("ex")) {
                throw new IllegalArgumentException("예외 발생");
            }
            sleep(1000);
            helloTraceV1.end(status);

        } catch (Exception e) {
            helloTraceV1.exception(status, e);
            throw e;
        }

    }


    private void sleep (long millis) {

        try{
            Thread.sleep(millis);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

 

@Service
@RequiredArgsConstructor
public class OrderserviceV2 {

    private final OrderRepoV2 orderRepo;
    private final HelloTraceV2 helloTraceV2;

    public void OrderItem(TraceId traceId, String item) {

        TraceStatus status = null;

        try{
            status = helloTraceV2.beginSync(traceId,"OrderServiceV2.OrderItem()");
            orderRepo.save(status.getTraceId(),item); // 변경된 부분
            helloTraceV2.end(status);
        } catch (Exception e) {
            helloTraceV2.exception(status, e);
            throw e;
        }
    }
}

각 변경 된 부분을 보자면, Controller를 제외한 Repository와 Service에서는

begin() 대신 beginSync()를 사용하여, TraceId 값을 함께 넘겨주며 TraceId를 동기화 해준다.

 

그리고 Service 계층의 OrderItem이 TraceId 객체를 파라미터로 받을 수 있도록하여,

Controller에서 생성한 TraceStatus의 TraceId값을 넘겨줄 수 있도록 변경되었다.

이를 파악해보면, 아래와 같은 형태일 것이다.

 

 

 

변경된 코드를 바탕으로 실행하였을 때, 이제 로그의 형태가 아래와 같이 출력된다.

고유 ID값의 모습도 일관된 모습이며, 깊이에 따라 로그의 흐름을 한 눈에 파악할 수 있어졌다.

따라서, 로그 추적 기능의 요구 사항을 모두 적용할 수 있었다.

 

남은 문제들

그런데 아직 남은 문제들이 있다.

 

먼저 http 요청의 구분과 깊이를 표현하기 위해서 TraceId의 동기화가 필요하고,

이를 위해서는 관련한 모든 메서드의 파라미터의 수정이 필요하다는 것이다.

 

또한, 만약 컨트롤러부터 시작하는 호출이 아닌 다른 서비스부터 호출하는 상황이라면 파라미터로 넘길 TraceId가 결여된 상태일 것이다.

 

이런 방법들을 해결하기 위한 기술과 방법들을 이어서 다뤄보자.