로그 추적기 V1 - 적용

앞서 만든 로그추적기를 적용해보자.

 

1. OrderControllerV1

---

• 앞의 테스트 처럼 단순하게 trace.begin(), trace.end()로 끝나는 것이 아니라 
• 예외 처리를 위해 try-catch 구문을 사용한다.
• 예외가 발생해도 로그를 남길 수 있어야 한다. 이 때 예외 상황에서 로그를 남기기 위해 프로그램 흐름을 변경해서는 안된다.
• 즉, 예외를 먹어버리지 말고 다시 던져줘야 한다.

@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; //예외를 반드시 다시 던져줘야 함.
        }
    }
}

 

 

2. OrderRepositoryV1

---

@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();
        }
    }
}

 

 

3. OrderServiceV1

---

@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; //예외를 반드시 다시 던져줘야 함.
        }

    }
}

 

 

4. 실행

---

• 현재는 traceId 객체가 매 번 만들어진다.
  • trace.begin()을 호출할 때 마다 TraceId 만듦.
• 따라서 Controller, Service, Repository 각각 TraceId를 생성하기 때문에 traceId가 다 다르다.

2021-11-19 23:43:37.014  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [f2724b3f] OrderController.request()
2021-11-19 23:43:37.015  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [4df6a51a] OrderService.orderItem()
2021-11-19 23:43:37.015  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [1161028a] OrderRepository.save()
2021-11-19 23:43:38.017  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [1161028a] OrderRepository.save() time=1002ms
2021-11-19 23:43:38.018  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [4df6a51a] OrderService.orderItem() time=1003ms
2021-11-19 23:43:38.019  INFO 8324 --- [nio-8080-exec-1] hello.advanced.hellotrace.HelloTraceV1   : [f2724b3f] OrderController.request() time=1005ms

ex) 정상 흐름 예시

[11111111] OrderController.request()
[22222222] OrderService.orderItem()
[33333333] OrderRepository.save()
[33333333] OrderRepository.save() time=1000ms
[22222222] OrderService.orderItem() time=1001ms
[11111111] OrderController.request() time=1001ms

 

• 예외 흐름

2021-11-19 23:49:20.382  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [ffd1fd9c] OrderController.request()
2021-11-19 23:49:20.383  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [cb2edf5d] OrderService.orderItem()
2021-11-19 23:49:20.383  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [d75b3c8a] OrderRepository.save()
2021-11-19 23:49:20.383  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [d75b3c8a] OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생
2021-11-19 23:49:20.384  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [cb2edf5d] OrderService.orderItem() time=1ms ex=java.lang.IllegalStateException: 예외 발생
2021-11-19 23:49:20.384  INFO 8324 --- [nio-8080-exec-3] hello.advanced.hellotrace.HelloTraceV1   : [ffd1fd9c] OrderController.request() time=2ms ex=java.lang.IllegalStateException: 예외 발생
2021-11-19 23:49:20.407 ERROR 8324 --- [nio-8080-exec-3] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.IllegalStateException: 예외 발생] with root cause

 

 

 

5. 남은 문제

---

• 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력
• 애플리케이션의 흐름을 변경하면 안됨
• 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨
• 메서드 호출에 걸린 시간
• 정상 흐름과 예외 흐름 구분
  
  • 예외 발생시 예외 정보가 남아야 함
• 메서드 호출의 깊이 표현
• HTTP 요청을 구분
  
  • HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 
  • 트랜잭션 ID (DB 트랜잭션X)
• 아직 구현하지 못한 요구사항
  • 메서드 호출의 깊이를 표현하고, 
  • 같은 HTTP 요청이면 같은 트랜잭션 ID를 남기는 것이다.
  • 이 기능은 직전 로그의 깊이와 트랜잭션 ID가 무엇인지 알아야 할 수 있는 일이다.
  • 예를 들어서 OrderController.request() 에서 로그를 남길 때 어떤 깊이와 어떤 트랜잭션 ID를
  • 사용했는지를 그 다음에 로그를 남기는 OrderService.orderItem() 에서 로그를 남길 때 알아야한다.
  • 결국 현재 로그의 상태 정보인 트랜잭션ID 와 level 이 다음으로 전달되어야 한다.
  • 정리하면 로그에 대한 문맥( Context ) 정보가 필요하다.3

 

 

6. GitHub : 211119 Log Tracer V1

---

GitHub - bsh6463/Spring_Advanced: initial