
spring-advanced 이름의 프로젝트를 생성했습니다.
상품을 주문하는 프로세스로 가정하고, 일반적인 웹 애플리케이션에서 Controller -> Service -> Repository로 이어지는 흐름를 단순히 만들어보겠습니다.
OrderRepositoryV0
package com.example.springadvanced.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();
}
}
}
@Repository: 컴포넌트 스캔의 대상이 된다. 따라서 스프링 빈으로 자동 등록된다.OrderServiceV0
package com.example.springadvanced.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);
}
}
@Service: 컴포넌트 스캔의 대상이 된다.@RequiredArgsConstructor: 초기화 되지않은 final필드나, @NonNull이 붙은 필드에 대해 생성자를 주입OrderControllerV0
package com.example.springadvanced.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";
}
}
@RestController: 컴포넌트 스캔과 스프링 Rest 컨트롤러로 인식된다. 요구사항
TraceId, TraceStatus클래스를 만들어보자.TraceId
package com.example.springadvanced.trace;
import java.util.UUID;
public class TraceId {
private String id;
private int level;
public TraceId() {
this.id = createId();
this.level = 0;
}
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;
}
public String getId() {
return id;
}
public int getLevel() {
return level;
}
}
TraceId라는 개념을 만들었다.TraceId는 단순히 id(트랜잭션ID)와 level정보를 함께 가지고 있다.TraceStatus
package com.example.springadvanced.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 Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
public TraceId getTraceId() {
return traceId;
}
}
TraceStatus는 로그를 시작할 때의 상태 정보를 가지고 있다. 이 상태 정보는 로그를 종료할 때 사용된다.HelloTraceV1
package com.example.springadvanced.trace.hellotrace;
import com.example.springadvanced.trace.TraceId;
import com.example.springadvanced.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();
}
}
공개 메서드
로그 추적기에서 사용되는 공개 메서드는 다음 3가지이다.
begin(..)end(..)exception(..)하나씩 알아보자
TraceStatus begin(String message)TraceStatus를 반환한다.void end(TraceStatus status)TraceStatus)를 전달 받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.void exception(TraceStatus status, Exception e)TraceStatus, Exception정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.HelloTraceV1Test
package com.example.springadvanced.trace.hellotrace;
import com.example.springadvanced.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());
}
}

애플리케이션에 우리가 개발한 로그 추적기를 적용해보자!
OrderControllerV1
package com.example.springadvanced.app.v1;
import com.example.springadvanced.trace.TraceStatus;
import com.example.springadvanced.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; //예외를 꼭 다시 던져주어야 한다.
}
}
}
begin()의 결과 값으로 받은 TraceStatus status값을 end(), exception()에 넘겨야 한다.try상위에 TraceStatus status코드를 선언해야 한다. 만약 try안에서 TraceStatus status를 선언하면 try블록안에서만 해당 변수가 유효하기 때문에 catch블록에 넘길 수 없다. 따라서 컴파일 오류가 발생한다.throw e: 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 로그는 애플리케이션에 흐름에 영향을 주면 안된다. 로그 때문에 예외가 사라지면 안된다.OrderServiceV1
package com.example.springadvanced.app.v1;
import com.example.springadvanced.trace.TraceStatus;
import com.example.springadvanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;
@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;
}
}
}
OrderRepositoryV1
package com.example.springadvanced.app.v1;
import com.example.springadvanced.trace.TraceStatus;
import com.example.springadvanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;
@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;
}
}
private void sleep(int millis) {
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
정상 흐름 실행

예외 발생 시


참고: 아직 level 관련 기능을 개발하지 않았다. 따라서 level 값은 항상 0이다. 그리고 트랜잭션ID 값도
다르다.
트랜잭션ID와 level을 다음 로그에 넘겨주면 된다.트랜잭션ID와 level은 TraceId에 포함되어 있다. 따라서 TraceId를 다음 로그에 넘겨주면 된다.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);
}
TraceId에서 createNextId()를 통해 다음 ID를 구한다.createNextId()의 TraceId생성 로직은 다음과 같다.HelloTraceV2Test
package com.example.springadvanced.trace.hellotrace;
import com.example.springadvanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;
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("hello");
TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
trace.exception(status2, new IllegalStateException());
trace.exception(status1, new IllegalStateException());
}
}

트랜잭션ID를 유지하고 level을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다.메서드 호출의 깊이를 표현하고, HTTP 요청도 구분해보자.
OrderController.request()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 다음 차례인 OrderService.orderItem()에서 로그를 남기는 시점에 알아야한다.
OrderControllerV2
package com.example.springadvanced.app.v2;
import com.example.springadvanced.trace.TraceStatus;
import com.example.springadvanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;
@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;
}
}
}
TraceStatus status= trace.begin()에서 반환 받은 TraceStatus에는 트랜잭션ID 와 level정보가 있는 TraceId가 있다.orderService.orderItem()을 호출할 때 TraceId를 파라미터로 전달한다.TraceId를 파라미터로 전달하기 위해 OrderServiceV2.orderItem()의 파라미터에 TraceId를 추가해야 한다.정상 호출

예외 실행

남은 문제
TraceId동기화가 필요하다.TraceId의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.begin()을 호출하고, 처음이 아닐때는 beginSync()를 호출해야 한다.TraceId가 없다.참고
김영한: 스프링 핵심 원리 - 고급편(인프런)
Github - https://github.com/b2b2004/Spring_ex