내가 공부한것을 올리며, 중요한 단원은 저 자신도 곱씹어 볼겸 상세히 기록하고 얕은부분들은 가겹게 포스팅 하겠습니다.
1. 예제 프로젝트 만들기 - V0
이번시간에는 아주 간단한 예제 프로젝트를 만들었다. 코드 설명할 부분도없다.
▶ OrderRepositoryV0
@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();
}
}
}
▶ OrderServiceV0
@Service
@RequiredArgsConstructor
public class OrderServiceV0 {
private final OrderRepositoryV0 orderRepository;
public void orderItem(String itemId) {
orderRepository.save(itemId);
}
}
▶ OrderControllerV0
@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {
private final OrderServiceV0 orderService;
@GetMapping("/v0/request")
public String request(@RequestParam String itemId) {
orderService.orderItem(itemId);
return "ok";
}
}
2. 로그 추적기 V1 - 프로토타입 개발
우리의 로거는 다음과 같이 로그를 남기게 될 것 이다!
정상 요청
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem()
[796bccd9] | |-->OrderRepository.save()
[796bccd9] | |<--OrderRepository.save() time=1004ms
[796bccd9] |<--OrderService.orderItem() time=1014ms
[796bccd9] OrderController.request() time=1016ms
이번시간에는 로거의 프로토타입 코드를 작성할 것 이다!
우선 Transaction Id 와 depth를 하나의 객체로 관리할 것 이다. 바로 TraceId Class 이다!
▶ TraceId 클래스
로그 추적기는 트랜잭션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
코드는 다음과 같다
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;
}
}위 코드 중에 createNextId() 메서드 정도만 확인해보면 될것같다.
createNextId는 현재 TraceId 를 유지하면서, 다음 TraceId 를 만들게 된다.
이때 만들어진 TraceId의 id 는 기존과 같고, level 은 하나 증가하게 된다.
다음으로는 추적 상태를 표현해줄 TraceStatus Class를 만들어보자!
▶ 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 TraceId getTraceId() {
return traceId;
}
public Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
}
TraceStatus 는 로그의 상태 정보를 나타낸다!
[796bccd9] OrderController.request() //로그 시작
[796bccd9] OrderController.request() time=1016ms //로그 종료TraceStatus 는 로그를 시작할 때의 상태 정보를 가지고 있다.
따라서 종료시점의 시간에서 상태 정보로 가지고 있는 시작 시간을 빼면 전체 수행 시간을 출력해줄 수 있다.
- traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
- startTimeMs : 시작~종료까지 전체 수행 시간을 구할 수 있다.
- message : 시작시 사용한 메시지이다.
이번에는 TraceId , TraceStatus 를 사용해서 실제 로그를 생성하고, 처리하는 기능을 개발해보자!
▶ HelloTraceV1
@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가지 메서드가 존재한다
1) begin() : 로그를 시작하는 역할을 한다.
로그 메시지를 파라미터로 받아서 시작 로그를 출력하며, 응답 결과로 현재 로그의 상태인 TraceStatus 를 반환한다.
2) end() : 로그를 정상 종료한다.
파라미터로 시작 로그의 상태( TraceStatus )를 전달 받는다.
이 값을 활용해서 실행 시간을 계산하고, 종료시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
정상 흐름에서 호출한다.
예를 들면 다음과 같다
[796bccd9] |<--OrderService.orderItem() time=1014ms
3) exception() : 로그를 예외 상황으로 종료한다.
TraceStatus , Exception 정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.
예외가 발생했을 때 호출한다.
예를 들면 다음과 같다
[b7119f27] |<X-OrderService.orderItem() time=10ms ex=java.lang.IllegalStateException: 예외 발생!
이제 간단하게 코드로 살펴보자. 실행하기 편해서 test상으로 작성하기는 했지만, 실질적으로 검증을 하는 테스트코드는 아니다.
@Test
public void begin_end() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("shine");
trace.end(status);
}실행 결과는 다음과 같다.
@Test
public void begin_exception() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("hello");
trace.exception(status, new IllegalArgumentException());
}실행 결과는 다음과 같다.
인자로 받은 예외의 종류까지 출력해주고 있다.
다음 단락에서는 이전에 만든 상품 주문 코드에 우리의 로거를 적용시켜보자!
3. 로그 추적기 V1 - 적용
이번에는 컨트롤러에 우리의 로거를 적용시켜보자. 다음고 같다!
@RestController
@RequiredArgsConstructor
public class OrderControllerV1 {
private final OrderServiceV1 orderService;
private final HelloTraceV1 trace;
@GetMapping("/v1/request")
public String request(@RequestParam String itemId) {
TraceStatus status = trace.begin("OrderController.request()"); // 로거 시작
orderService.orderItem(itemId);
trace.end(status); // 로거 종료
return "ok";
}
}위와 같이만 사용한다면 정상작동 하게 될것이다. 다음 URI로 요청을 보내보자.
http://localhost:8080/v1/request?itemId=hello결과는 다음고 같이 나온다.
시작지점과, 종료지점이 출력 되었으며 시간 또한 정상적으로 나오고 있다.
문제는 예외가 발생했을 경우 이다. 다음과 같이 요청을 보내보자
http://localhost:8080/v1/request?itemId=ex다음과 같이 시작 부분만 로그로 출력되게 되어버린다.
즉, 예외가 발생해도 로그가 출력되도록 해줘야 한다!
우선 간단하게 try catch 를 통해 처리해보자. 다음과 같다.
@GetMapping("/v1/request")
public String request(@RequestParam 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;
}
}catch문 안에서는 꼭 다시 Exception을 throw 해줘야 한다.
그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다.
로그는 애플리케이션에 흐름에 영향을 주면 안된다. 로그 때문에 예외가 사라지면 안된다.
이후 다시 다음 URI에 요청을 보내보자
http://localhost:8080/v1/request?itemId=ex결과는 다음과 같다.
같은 방식으로 Service, Repository 또한 처리해주자.
@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;
}
}
}@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();
}
}
}정상 실행 결과는 다음과 같다.
예외가 발생한 경우는 다음과 같다.
아직 트랜잭Id값의 동기화 작업과, 시각적인 depth로 Level을 표시해주는 작업은 하지 않았다.
원래 우리가 목표로 하는 결과에서는 같은 요청범위 에서는 트랜잭션ID가 동일해야 한다. 하지만 우리는 다르다.
왜냐하면 Controller, Service, Repository에서 모두 각자가 trace.begin()을 호출하면서 new TraceId()를 호출하게 된다.
즉, Controller, Service, Repository 각각이 서로 다른 TraceId 객체를 가지고 로그를 출력한 것 이다.
이를 그림으로 확인하면 다음과 같다.
아직 구현하지 못한 요구사항은 메서드 호출의 깊이를 표현하고, 같은 HTTP 요청이면 같은 트랜잭션 ID를 남기는 것이다.
이 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일이다.
예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지를 그 다음 OrderService.orderItem() 에서 로그를 남길 때 알아야한다.
결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다.
정리하면 로그에 대한 문맥( Context ) 정보가 필요하다.
우선 이를 parameter방식으로 다음단락에서 해결해보자!
4. 로그 추적기 V2 - 파라미터로 동기화 개발
현재 로그의 상태 정보인 트랜잭션ID 와 level 은 TraceId 에 포함되어 있다.
따라서 TraceId 를 다음 로그에 넘겨주면 된다. 이 기능을 추가한 HelloTraceV2 를 개발해보자.
V2 에서는 다른 부분은 전부 동일하고, begin()부분만 변경해주면 된다.
@Slf4j
@Component
public class HelloTraceV2 {
// 생략...
public TraceStatus beginSync(TraceId beforeTraceId, String message) {
TraceId nowTraceId = beforeTraceId.createNextId();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", nowTraceId.getId(), addSpace(START_PREFIX, nowTraceId.getLevel()), message);
return new TraceStatus(nowTraceId, startTimeMs, message);
}
// 생략...
}beginSync() 메서드의 인자로 이전 TraceId를 전달받고 있다.
이를 받아서 createNextId()를 호출하여 다음 TraceId를 할당받는 것 이다!
결과를 간단하게 확인해보자.
@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 을 통해 메서드 호출의 깊이를 표현하는 것을 확인할 수 있다.
다음 단락에서는 beginSync()를 사용해서 V2를 동기화 시켜보자!
5. 로그 추적기 V2 - 적용
이번 단락에서는 메서드 호출의 깊이를 표현하고, HTTP 요청도 구분해보자.
실행되는 흐름은 다음과 같을 것 이다.
위와같이 하려면 처음 로그를 남기는 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 다음 차례인 OrderService.orderItem() 에서 로그를 남기는 시점에 알아야한다.
=> 결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달!
이 정보는 TraceStatus.traceId 에 담겨있다. 따라서 traceId 를 컨트롤러에서 서비스를 호출할 때 넘겨주면 된다.
우선 코드를 HelloTraceV2를 사용하도록 변경해보자!
▶ OrderControllerV2
@GetMapping("/v2/request")
public String request(@RequestParam String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderController.request()");
orderService.orderItem(status.getTraceId(), itemId); // 인자로 TraceId를 넘김
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
▶ OrderServiceV2
public void orderItem(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderService.orderItem()");
orderRepository.save(status.getTraceId(), itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}V2에서부터는 beginSync를 사용하고 있다.
이후 다시 Repository에 save를 요청할때 Service계층의 TraceId 객체를 인자로 넘긴다.
▶ OrderRepositoryV2
public void save(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderRepository.save()");
//저장 로직
if (itemId.equals("ex")) {
throw new IllegalStateException("예외 발생!");
}
sleep(1000);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
이제 실행 결과를 확인해 보자. 우선 정상적인 경우는 다음과 같다.
우리가 원했던 모습으로 출력되고 있다!
다음으로는 예외가 발생할 경우를 살펴보자!
잘 출력되는 것이 확인된다.
하지만 몇가지 문제점들이 남아있다.
우선 TraceId 의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.
만에하나 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하며, 해당 인터페이스의 구현체들 모두 수정해줘야 한다...
또한 로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다.
만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황이라면 파리미터로 넘길 TraceId 가 없다.
'BackEnd > Spring' 카테고리의 다른 글
| [Spring] 쓰레드 로컬 - ThreadLocal - 2 (0) | 2022.08.05 |
|---|---|
| [Spring] 쓰레드 로컬 - ThreadLocal - 1 (0) | 2022.08.04 |
| [Spring] 스프링의 3대 요소 (IoC/DI, PSA, AOP) (5) | 2022.07.22 |
| [Spring] Spring 환경변수 설정파일 선택하기 (2) | 2022.06.12 |
| [Spring] @RequestBody에 기본생성자만 필요하고 Setter는 필요없는 이유 - 2 (10) | 2022.06.12 |
댓글