인프런 김영한님의 '스프링 핵심 원리-고급편' 강의 보러가기
https://www.inflearn.com/course/%EC%8A%A4%ED%94%84%EB%A7%81-%ED%95%B5%EC%8B%AC-%EC%9B%90%EB%A6%AC-%EA%B3%A0%EA%B8%89%ED%8E%B8/dashboard
모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력
애플리케이션의 흐름을 변경하면 안됨
메서드 호출에 걸린 시간
정상 흐름과 예외 흐름 구분
메서드 호출의 깊이 표현
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: 예외 발생!
먼저 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId , TraceStatus 클래스를 만들어보자
package hello.advanced.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;
}
}
로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다.
여기서는 트랜잭션ID와 깊이를 표현하는 level을 묶어서 TraceId 라는 개념을 만들었다.
TraceId 는 단순히 id (트랜잭션ID)와 level 정보를 함께 가지고 있다.
[796bccd9] OrderController.request() //트랜잭션ID:796bccd9, level:0
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID:796bccd9, level:1
[796bccd9] | |-->OrderRepository.save()//트랜잭션ID:796bccd9, level:2
TraceId 를 처음 생성하면 createId() 를 사용해서 UUID를 만들어낸다. UUID가 너무 길어서 여기서는
앞 8자리만 사용한다. 이 정도면 로그를 충분히 구분할 수 있다. 여기서는 이렇게 만들어진 값을 트랜잭션ID
로 사용한다.
ab99e16f-3cde-4d24-8241-256108c203a2 //생성된 UUID
ab99e16f //앞 8자리만 사용
다음 TraceId 를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다. 대신에 깊이가 하나
증가한다.
실행 코드: new TraceId(id, level + 1)
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID가 같다. 깊이는 하나 증가한다.
따라서 createNextId() 를 사용해서 현재 TraceId 를 기반으로 다음 TraceId 를 만들면 id 는 기존과
같고, level 은 하나 증가한다.
createNextId() 의 반대 역할을 한다.
id 는 기존과 같고, level 은 하나 감소한다.
첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드
package hello.advanced.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 TraceId getTraceId() {
return traceId;
}
public Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
}
로그의 상태 정보를 나타낸다.
로그를 시작하면 끝이 있어야 한다.
[796bccd9] OrderController.request() //로그 시작
[796bccd9] OrderController.request() time=1016ms //로그 종료
TraceStatus 는 로그를 시작할 때의 상태 정보를 가지고 있다. 이 상태 정보는 로그를 종료할 때 사용된다.
package hello.advanced.trace.HelloTraceV1;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
@Slf4j
@Component
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.getId(), 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.getId(), 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.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();
}
}
메서드의 메인 로직 전에 호출할 메서드이다. begin 은 호출 깊이가 0인 메서드에서만 실행된다. 다음 호출된 메서드에서는 동일한 Id 를 갖도록 해야하기 때문이다. 생성한 Id 와 message 를 출력한다.
begin 과 마찬가지로 메서드 시작시 호출할 메서드이다. 대신 상위 메서드에서 생성한 TraceId 를 파라미터로 받는다. 동일한 Id를 갖으므로 TraceId 의 level 만 1을 증가시켜서 사용한다. Id 와 message를 출력한다.
메서드의 메인 로직이 끝나고 정상적으로 종료되었을 경우 호출하는 메서드이다. complete 를 호출한다.
메서드에서 예외가 발생해 비정상 종료되었을 경우 호출하는 메서드이다. complete 를 호출한다.
메서드 종료시 공통적으로 호출하는 메서드이다. 정상 종료시 현재 level 에서 id, 소요시간, 메시지를 출력한다. 비정상 종료시 동일한 정보와 추가로 예외를 출력한다.
@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {
private final OrderServiceV2 orderServiceV2;
private final HelloTraceV2 trace;
@GetMapping("/v2/request")
public String request(String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderController.request()");
orderServiceV2.orderItem(itemId, status.getTraceId());
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
- 컨트롤러에서 서비스로 문맥을 유지하기 위해 service 메서드를 호출 시 TraceId 객체를 파라미터로 넘긴다.
- 로그 추적을 시작하는 로그 추적기의 begin 메서드를 실행한다.
package hello.advanced.v2;
import hello.advanced.trace.HelloTraceV1.HelloTraceV1;
import hello.advanced.trace.HelloTraceV1.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;
@Service
@RequiredArgsConstructor
public class OrderServiceV2 {
private final OrderRepositoryV2 orderRepository;
private final HelloTraceV2 trace;
public void orderItem(String itemId, TraceId traceId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderService.orderItem()");
orderRepository.save(itemId, status.getTraceId());
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
- 서비스 계층에서 리포지토리 계층으로의 문맥을 유지하기 위해 repository 메서드를 호출 시 TraceId 객체를 파라미터로 넘긴다.
- 로그 추적을 동기화 하는 로그 추적기의 beginSync 메서드를 실행한다.
package hello.advanced.v2;
import hello.advanced.trace.HelloTraceV1.HelloTraceV1;
import hello.advanced.trace.HelloTraceV1.HelloTraceV2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {
private final HelloTraceV2 trace;
public void save(String itemId, TraceId traceId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderRepository.save()");
if (itemId.equals("ex")) {
throw new IllegalArgumentException("예외 발생!");
}
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();
}
}
}
- 로그 추적을 동기화 하는 로그 추적기의 beginSync 메서드를 실행한다.