예제 만들기

로그 추적기 만들기

정상 요청
[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: 예외 발생!

 

 

HelloTrace

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

 

 

 

 

 

 

---

적용

 

 

로그 추적기 적용

 

 

 

 

 

정상 실행 로그
[11111111] OrderController.request()
[22222222] OrderService.orderItem()
[33333333] OrderRepository.save()
[33333333] OrderRepository.save() time=1000ms
[22222222] OrderService.orderItem() time=1001ms
[11111111] OrderController.request() time=1001ms

예외 실행 로그
[5e110a14] OrderController.request()
[6bc1dcd2] OrderService.orderItem()
[48ddffd6] OrderRepository.save()
[48ddffd6] OrderRepository.save() time=0ms 
ex=java.lang.IllegalStateException: 예외 발생!
[6bc1dcd2] OrderService.orderItem() time=6ms 
ex=java.lang.IllegalStateException: 예외 발생!
[5e110a14] OrderController.request() time=7ms 
ex=java.lang.IllegalStateException: 예외 발생!

 

남은 문제

• 메서드 호출의 깊이 표현
• HTTP 요청을 구분
          HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
          트랜잭션 ID (DB 트랜잭션X)

 

 

 

 

---

파라미터로 동기화 개발

 

 

트랜잭션ID와 메서드 호출의 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션ID 와 level 을 다음 로그에 넘겨주면 된다.

 

 

 

 

HelloTrace 추가

//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);
}

 

 

 

 

begin_end_level2() - 실행 로그
[0314baf6] hello1
[0314baf6] |-->hello2
[0314baf6] |<--hello2 time=2ms
[0314baf6] hello1 time=25ms

begin_exception_level2() - 실행 로그
[37ccb357] hello
[37ccb357] |-->hello2
[37ccb357] |<X-hello2 time=2ms 
ex=java.lang.IllegalStateException
[37ccb357] hello time=25ms 
ex=java.lang.IllegalStateException

 

 

 

 

---

 적용

 

 

 

파라미터로 동기화 개발 적용

 

 

 

 

 

정상 실행 로그
[c80f5dbb] OrderController.request()
[c80f5dbb] |-->OrderService.orderItem()
[c80f5dbb] |   |-->OrderRepository.save()
[c80f5dbb] |   |<--OrderRepository.save() time=1005ms
[c80f5dbb] |<--OrderService.orderItem() time=1014ms
[c80f5dbb] OrderController.request() time=1017ms

예외 실행 로그
[ca867d59] OrderController.request()
[ca867d59] |-->OrderService.orderItem()
[ca867d59] | |-->OrderRepository.save() 
[ca867d59] | |<X-OrderRepository.save() time=0ms 
ex=java.lang.IllegalStateException: 예외 발생! 
[ca867d59] |<X-OrderService.orderItem() time=7ms
ex=java.lang.IllegalStateException: 예외 발생! 
[ca867d59] OrderController.request() time=7ms
ex=java.lang.IllegalStateException: 예외 발생!

 

 

 

※ 정리 : 모든 요구 사항 만족

 

 

 

 

 

☆ 남은 문제

• HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId 동기화가 필요하다.
• TraceId 의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.
       만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
• 로그를 처음 시작할 때는 begin() 을 호출하고, 처음이 아닐때는 beginSync() 를 호출해야 한다.
            만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라면 파리미터로 넘길 TraceId 가 없다.