[5] 로그 추적기 V1 - 적용
: 애플리케이션에 로그 추적기 적용하기
✔️ OrderControllerV1.java
@RestController // @Controller + @ResponseBody
@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; // (먹었으니 정상 흐름이 되어버림 그래서 )예외를 꼭 다시 던져주어야 한다.
}
}
}⬇️ 예외 발생해도 탈출하지 않도록 try catch처리
HelloTraceV1 trace:HelloTraceV1을 주입받음.
참고로HelloTraceV1은@Component어노테이션을 가졌기 때문에 컴포넌트 스캔 대상이다.
따라서 자동으로 스프링 빈으로 등록된다.
trace.begin("OrderController.request()"): 로그를 시작할 때 메시지 이름으로 컨트롤러 이름 + 메소드 이름을 줌.
이렇게 하면 어떤 컨트롤러와 메소드가 호출되었는지 로그로 편리하게 확인할 수 있다. (→ 물론 수작업)
throw e: 예외를 꼭 다시 던져줘야 함.
다시 던져주지 않으면 여기서 예외를 먹어버려, 이후 정상 흐름으로 동작해버린다.
로그는 애플리케이션 흐름에 영향을 주면 안된다. (로그 때문에 예외가 사라지면 안된다.)
단순히 trace.begin(), trace.end() 코드 두 줄만 적용하면 될 줄 알았는데 사실 그렇지 않다.
trace.exception()으로 예외 처리까지 해야하므로 지저분한 try, catch 코드가 추가된다.
begin()의 결과 값으로 받은 TraceStatus status 값을 end(), exception()에 넘겨야 한다.
결국 try, catch 블록 모두에 이 값을 넘겨야 한다.
따라서 try 상위에 TraceStatus status 코드를 선언해야 한다.
만약 try 안에서 TraceStatus status를 선언하면 try 블록 안에서만 해당 변수가 유효하기 때문에 catch 블록에 넘겨줄 수 없다. ➡️ 컴파일 오류
✔️ OrderServiceV1.java
@Service // @Service 안에 @Component가 있어 자동으로 컴포넌트 스캔의 대상이 됨(자동으로 스프링 빈 등록)
@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.java
@Repository // 안에 @Component가 있어 자동으로 컴포넌트 스캔 대상이 됨(스프링 빈 등록)
@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")) { // (다양한 예제를 위해)"ex"라는 것이 넘어오면 예외 발생시킬
throw new IllegalStateException("예외 발생!");
}
sleep(1000); // 상품을 저장하는데 1초 정도 걸린다고 가정
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 값도 다르다.
⬇️ 예외 발생
HelloTraceV1 덕분에 직접 로그를 하나하나 남기는 것보다는 편하게 여러 로그를 남길 수 있다.
📌 남은 요구사항
- 메소드 호출의 깊이 표현
- HTTP 요청을 구분
- HTTP 요청 단위로 특정 ID를 남겨 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분 가능하게 하기
- 트랜잭션 ID (DB 트랜잭션 X)
➡️ **로그에 대한 문맥(Context) 정보가 필요
[6] 로그 추적기 V2 - 파라미터로 동기화 개발
트랜잭션ID와 메소드 호출 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션ID와 level을 다음 로그에 넘겨주는 것이다.
현재 로그의 상태 정보인 트랜잭션ID, level은 TraceId에 포함되어 있다.
따라서 TraceId를 다음 로그에 넘겨주면 된다.
✔️ HelloTraceV2.java
...
// V2에서 추가
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);
}
...➡️ HelloTraceV1.java의 기존 코드는 동일하고 beginSync() 메소드가 추가됨.
beginSync()
: 기존TraceId에서createNextId()를 통해 다음 ID를 구한다.
createNextId()의TraceId생성 로직은
- 트랜잭션ID는 기존과 같이 유지하되
- 깊이를 표현하는 Level은 하나 증가 한다.
✔️ HelloTraceV2Test.java
public class HelloTraceV2Test {
@Test
void begin_end() {
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() {
HelloTraceV2 trace = new HelloTraceV2();
TraceStatus status1 = trace.begin("hello1");
TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
trace.exception(status2, new IllegalStateException());
trace.exception(status1, new IllegalStateException());
}
}처음에는 begin()을 사용하고, 그 이후에는 beginSync()를 사용하면 된다.
그리고 beginSync()를 호출할 때 직전 로그의 traceId 정보를 넘겨주어야 한다.
실행 로그를 보면 같은 트랜잭션ID를 유지하고, level을 통해 메소드 호출 깊이를 표현하고 있다.
[7] 로그 추적기 V2 - 적용
: 이제 애플리케이션에 적용하기
메소드 호출 깊이를 표현하고 HTTP 요청을 구분하려면 OrderController.request()에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를 사용했는지 다음 차례인 OrderService.orderItem()에서 로그를 남기는 시점에 알아야한다.
결국 현재 로그 상태 정보인 트랜잭션ID, level이 다음으로 전달되어야 한다.
이 정보는 TraceStatus.traceId에 담겨있다. 따라서 traceId를 컨트롤러에서 서비스를 호출할 때 넘겨주면 된다.
✔️ OrderControllerV2.java
...
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);
...➡️ V1코드에서 수정이 필요한 부분의 코드만 첨부하였다.
TraceStatus status = trace.begin()에서 반환받은TraceStatus에는트랜잭션ID와level정보가 있는TraceId가 있다.orderService.orderItem()을 호출할 때TraceId를 파라미터로 전달한다.TraceId를 파라미터로 전달하기 위해OrderServiceV2.orderItem()의 파라미터에TraceId를 추가해야 한다.
✔️ OrderServiceV2.java
...
private final OrderRepositoryV2 orderRepository;
private final HelloTraceV2 trace;
public void orderItem(TraceId traceId, String itemId) {
TraceStatus status = null;
try { // 정상 실행시
status = trace.beginSync(traceId, "OrderService.orderItem()");
orderRepository.save(status.getTraceId(), itemId);
...➡️ V1코드에서 수정이 필요한 부분의 코드만 첨부하였다.
orderItem()은 파라미터로 전달 받은traceId를 사용해trace.beginSync()를 실행한다.beginSync()는 내부에서 다음traceId를 생성하면서트랜잭션ID는 유지하고level은 하나 증가시킨다.beginSync()가 반환한 새로운TraceStatus를orderRepository.save()를 호출하면서 파라미터로 전달한다.TraceId를 파라미터로 전달하기 위해orderRepository.save()의 파라미터에TraceId를 추가해야 한다.
✔️ OrderRepositoryV2.java
...
private final HelloTraceV2 trace;
public void save(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderRepository.save()");
...➡️ V1코드에서 수정이 필요한 부분의 코드만 첨부하였다.
save()는 파라미터로 전달받은traceId를 사용해trace.beginSync()를 실행한다.beginSync()는 내부에서 다음traceId를 생성하면서트랜잭션ID는 유지하고level은 하나 증가시킨다.beginSync()는 이렇게 갱신된traceId로 새로운TraceStatus를 반환한다.trace.end(status)를 호출하면서 반환된TraceStatus를 전달한다.
위의 로그를 보면 같은 HTTP 요청에 대해 트랜잭션ID가 유지되고, level도 잘 표현되는 것을 확인할 수 있다.
남은 문제
- HTTP 요청을 구분하고 깊이를 표현하기 위해
TraceId동기화가 필요하다. TraceId의 동기화를 위해 관련 메소드의 모든 파라미터를 수정해야 한다.
- 만약 인터페이스가 있다면 인터페이스까지 모두 수정해야 함,,- 로그를 처음 시작할 땐
begin()호출, 처음이 아닐 땐beginSync()호출 → 이렇게 각 다른 것을 호출해야 함
- 만약 컨트롤러를 통해 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황이라면 파라미터로 넘길TraceId가 없다.
HTTP 요청을 구분하고 깊이를 표현하기 위해 TraceId를 파라미터로 넘기는 방법 말고 다른 대안은 없는지 생각해볼 필요가 있다.
➡️ 다음 시간에 해결
