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