[Spring] 로그 출력기 만들기 (쓰레드 로컬 사용)

요구사항

1. 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력

  - 애플리케이션의 흐름을 변경하면 안됨
  - 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨
2. 메서드 호출에 걸린 시간 출력
3. 정상 흐름과 예외 흐름 구분
   - 예외 발생시 예외 정보가 남아야 함
4. 메서드 호출의 깊이 표현
5. HTTP 요청을 구분
    - HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함

 

 

먼저 로그정보를 담는 TraceStatus 와 TraceId 객체를 만든다.

public class TraceId {

    private String id;
    private int level;

    public TraceId() {
        this.id = createId();
        this.level = 0;
    }

    public TraceId(String id, int level) {
        this.id = id;
        this.level = level;
    }
	
    // Http 요청별 구분을 위한 UUID 생성 (8자리)
    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);
    }
	
    // 레벨이 0일때 출력을 위한 확인 메서드
    public boolean isFirstLevel() {
        return level == 0;
    }

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

public class TraceStatus {
	
    // 호출레벨과, Id를 가지고 있는 TraceId를 필드로 가진다.
    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;
    }
}

 

로그 출력을위한 정보를 담는 두 객체를 완성했다.

본격적으로 로그를 출력하는 기능을 하는 ThreadLogTrace 객체를 생성하자 

향후 로직 변경을 위해 LogTrace인터페이스를 구현하는 방식으로 설계했다.

public interface LogTrace {

    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

@Slf4j
public class ThreadLocalLogTrace implements LogTrace{

    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";
	
    // 쓰레드 로컬로 동시성 문제를 예방한다.
    private final ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();
	
    // TraceId를 생성하고 시작시간, 호출메시지를 이용하여, TraceStatus 객체를 생성한다.
    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder.get();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}",
                traceId.getId(),
                addSpace(START_PREFIX,
                traceId.getLevel()),
                message);
        return new TraceStatus(traceId, startTimeMs, message);
    }
	
    // 처음 호출되는 경우, new TraceId를 생성
    // 처음 호출 아니면, level이 증가한 TraceId를 생성
    private void syncTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId == null) {
            traceIdHolder.set(new TraceId());
        } else {
            traceIdHolder.set(traceId.createNextId());
        }
    }
	
    // TraceStatus 를 이용하여, 종료로직 출력을 실행한다. 
    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }
	
    // TraceStatus 를 이용하여, 종료로직 출력을 실행한다. 예외정보를 함께 전달한다.
    @Override
    public void exception(TraceStatus status, Exception e) {
        complete(status, e);
    }

    private void complete(TraceStatus status, Exception e) {
    	// 종료 시간을 측정, TraceStatus의 시작시간을 이용하여 실행시간을 구한다.
        Long stopTimeMillis = System.currentTimeMillis();
        long resultTimeMs = status.getStartTimeMs() - stopTimeMillis;
        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());
        }

        releaseTraceId();
    }
	
    // 로그 출력이 완료된 경우, 레벨을 감소시키거나, TraceId를 지운다.
    // 쓰레드 로컬은 쓰레드 완료시 반드시 값을 지워줘야 한다.
    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove();
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }
	
    // 호출레벨에 따라 출력메시지 생성하는 로직 
    private Object 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();
    }
}

 

이제 로그 출력 기능이 잘 작동하는지 테스트 코드를 통해 확인해보자

@Slf4j
class ThreadLocalLogTraceTest {

    ThreadLocalLogTrace trace = new ThreadLocalLogTrace();
	
    /** 콘솔 출력 결과
    * [3b331fac] hello1
    * [3b331fac] |-->hello2
    * [3b331fac] |<--hello2 time=0ms
    * [3b331fac] hello1 time=-5ms
    */
    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.end(status2);
        trace.end(status1);
    }
   
    /** 콘솔 출력 결과
    * [61d05c01] hello1
    * [61d05c01] |-->hello2
    * [61d05c01] |<X-hello2 time=0ms ex=java.lang.IllegalStateException
    * [61d05c01] hello time=0ms ex=java.lang.IllegalStateException
    */
    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

 

로그 출력 기능을 완성했다. 이제 스프링의 여러 디자인 패턴을 활용하여 로그 출력 기능을 사용해보자