programmer.cwchoiit

참고자료

목표

ThreadLocal이 무엇인지, 언제 사용되는지를 알아보는 포스팅이다. 한단계씩 차근 차근 알아가보자. 이 ThreadLocal에 대해 공부하기 위해 정말 긴 서사가 있을 예정이다. 그런데 꽤나 그 과정이 다 의미가 있고, 왜 ThreadLocal을 사용해야만 했는지를 알아가는 과정이니까 하나씩 차근차근 공부해보자!

예제 프로젝트 만들기 V0

우선, 하나씩 차근차근 따라해보자. 아래 코드를 우선 만들어보자.

OrderRepositoryV0

package cwchoiit.springadvanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV0 {

    public void save(String itemId) {
        if (itemId.equals("ex")) {
            throw new IllegalStateException("예외 발생!");
        }
        sleep(1000);
    }

    private void sleep(int ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

OrderServiceV0

package cwchoiit.springadvanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV0 {

    private final OrderRepositoryV0 orderRepository;

    public void orderItem(String itemId) {
        orderRepository.save(itemId);
    }
}

OrderControllerV0

package cwchoiit.springadvanced.app.v0;

import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {

    private final OrderServiceV0 orderService;

    @GetMapping("/v0/request")
    public String request(String itemId) {
        orderService.orderItem(itemId);
        return "ok";
    }
}

로그 추적기 - 요구사항 분석

애플리케이션이 커지면서 점점 모니터링과 운영이 중요해지는 단계이다. 어떤 부분에서 병목이 발생하는지, 어떤 부분에서 예외가 발생하는지를 로그를 통해 확인하는 것이 점점 중요해지고 있다. 기존에는 개발자가 문제가 발생한 다음에 관련 부분을 어렵게 찾아서 로그를 하나하나 직접 만들어서 남겼다. 로그를 미리 남겨둔다면 이런 부분을 손쉽게 찾을 수 있을 것이다. 이 부분을 개선하고 자동화하는 것이 미션이다.

예시

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

로그 추적기 V1 - 프로토타입 개발

애플리케이션의 모든 로직에 직접 로그를 남겨도 되지만, 그것보다는 더 효율적인 개발 방법이 필요하다. 특히 트랜잭션 ID와 깊이를 표현하는 방법은 기존 정보를 이어 받아야 하기 때문에 단순히 로그만 남긴다고 해결할 수 있는 것은 아니다. 요구사항에 맞추어 애플리케이션에 효과적으로 로그를 남기기 위한 로그 추적기를 개발해보자. 먼저 프로토타입 버전을 개발해보자. 아마 코드를 모두 작성하고 테스트 코드까지 실행해보아야 어떤 것을 하는지 감이 올 것이다. 

TraceId

package cwchoiit.springadvanced.trace;

import java.util.UUID;

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 createPrevId() {
        return new TraceId(id, level - 1);
    }

    public boolean isFirstLevel() {
        return level == 0;
    }

    public String getId() {
        return id;
    }

    public int getLevel() {
        return level;
    }
}

• 로그 추적기는 트랜잭션ID와 깊이를 표현하는 방법이 필요하다. 여기서는 트랜잭션 ID와 깊이를 표현하는 level을 묶어서 TraceId라는 개념을 만들었다. TraceId는 단순히 id(트랜잭션 ID)와 level 정보를 함께 가지고 있다.

TraceStatus

package cwchoiit.springadvanced.trace;

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

• 로그의 상태 정보를 나타낸다.

HelloTraceV1

package cwchoiit.springadvanced.trace.hellotrace;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@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 startTime = System.currentTimeMillis();

        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTime, message);
    }

    public void end(TraceStatus status) {
        complete(status, null);
    }

    public void exception(TraceStatus status, Throwable ex) {
        complete(status, ex);
    }

    private void complete(TraceStatus status, Throwable ex) {
        long stopTime = System.currentTimeMillis();
        long resultTime = stopTime - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();

        if (ex == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTime);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTime, ex.getMessage());
        }
    }

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

• 이 HelloTraceV1을 사용해서 실제 로그를 시작하고, 종료할 수 있다. 그리고 로그를 출력하고 실행시간도 측정할 수 있다. 어디서 이 코드를 호출하는지는 이후에 차차 알게된다.
• @Component 애노테이션을 사용해서 스프링 빈으로 등록한다. 컴포넌트 스캔의 대상이 되고 싱글톤으로 만들어진다.

공개 메서드

로그 추적기에서 사용되는 공개 메서드는 다음 3가지이다.

• begin(...)
• end(...)
• exception(...)

하나씩 자세히 알아보자.

• TraceStatus begin(String message)
  • 로그를 시작한다.
  • 로그 메세지를 파라미터로 받아서 시작 로그를 출력한다.
  • 응답 결과로 현재 로그의 상태인 TraceStatus를 반환한다.
• void end(TraceStatus status)
  • 로그를 정상 종료한다.
  • 파라미터로 시작 로그의 상태(TraceStatus)를 전달 받는다. 이 값을 활용해서 실행 시간을 계산하고, 종료시에도 시작할 때와 동일한 로그 메시지를 출력할 수 있다.
  • 정상 흐름에서 호출한다.
• void exception(TraceStatus status, Throwable ex)
  • 로그를 예외 상황으로 종료한다.
  • TraceStatus, Throwable 정보를 함께 전달 받아서 실행시간, 예외 정보를 포함한 결과 로그를 출력한다.
  • 예외가 발생했을 때 호출한다.

비공개 메서드

• complete(TraceStatus status, Throwable ex)
  • end(), exception()의 요청 흐름을 한곳에서 편리하게 처리한다. 실행 시간을 측정하고 로그를 남긴다.
• String addSpace(String prefix, int level)
  • 다음과 같은 결과를 출력한다.
  • prefix: --->
    • level 0: 
    • level 1: |--->
    • level 2: |       |--->
  • prefix: <---
    • level 0:
    • level 1: |<---
    • level 2: |       |<---
  • prefix: <X--
    • level 0:
    • level 1: |<X--
    • level 2: |       |<X--

로그 추적기 V1 - 적용

이렇게 만든 로그 추적기를 이제 애플리케이션에 적용해보자. 

기존에 V0으로 만들었던 Controller, Service, Repository를 V1로 새로 만들어보자.

OrderControllerV1

package cwchoiit.springadvanced.app.v1;

import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@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("OrderControllerV1.request(String itemId)");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

• HelloTraceV1을 주입받는다. 어떤 요청이 들어왔을 때, 우선 가장 먼저 trace.begin("OrderControllerV1.request(String itemId)")를 실행한다. 이렇게 하면 어떤 컨트롤러와 메서드가 호출되었는지 로그로 편리하게 확인할 수 있다. 물론 간단해보이지는 않는다. 이후에 어떻게 이 코드가 점진적으로 아름다워 지는지 확인해보자.
• 단순하게 trace.begin(), trace.end() 코드 두 줄만 적용하면 될 줄 알았지만, 실상은 그렇지 않다. trace.exception()으로 예외까지 처리해야 하므로 지저분한 try - catch 코드가 추가된다. 
• begin()의 결과값으로 받은 TraceStatus status 값을 end(), exception()에 넘겨야 한다. 결국 try - catch 블록 모두에 이 값을 넘겨야 하므로 try 상위에 TraceStatus status 코드를 선언해야 한다.
• catch 블록에서는 throw e를 통해 예외를 꼭 다시 던져주어야 한다. 그렇지 않으면 여기서 예외를 먹어버리고, 이후에 정상 흐름으로 동작한다. 로그는 애플리케이션 흐름에 영향을 주면 안된다. 로그 때문에 예외가 사라지면 안된다.

OrderServiceV1

package cwchoiit.springadvanced.app.v1;

import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@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("OrderServiceV1.orderItem(String itemId)");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

OrderRepositoryV1

package cwchoiit.springadvanced.app.v1;

import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV1;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV1 {

    private final HelloTraceV1 trace;

    public void save(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepositoryV1.save(String itemId)");
            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 ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

이렇게 만든 Controller, Service, Repository를 가지고 이제 정상 실행과 예외 실행을 해보자. 아래와 같이 요청을 해보면 로그가 남는다.

# OrderControllerV1.request
GET http://localhost:8080/v1/request?itemId=ex

[df082bae] OrderControllerV1.request(String itemId)
[5e8339a2] OrderServiceV1.orderItem(String itemId)
[7a5354ed] OrderRepositoryV1.save(String itemId)
[7a5354ed] OrderRepositoryV1.save(String itemId) time=0ms ex=예외 발생!
[5e8339a2] OrderServiceV1.orderItem(String itemId) time=1ms ex=예외 발생!
[df082bae] OrderControllerV1.request(String itemId) time=2ms ex=예외 발생!

• 생각했던 것과 달리 정말 안 예쁘다. 하지만 지금은 이렇게 나오는게 맞다. 레벨 관련 기능을 개발하지 않았기 때문에. 또한 트랜잭션 ID도 다 다르다. 이 부분 역시 아직 개발되지 않았다. 결국 Controller, Service, Repository 다 다른 트랜잭션 ID를 가지게 된다.
• 쉽게 말해, Controller가 최초 호출 지점이라면 이 지점에서 만들어진 트랜잭션 ID가 컨트롤러가 호출하는 서비스, 서비스가 호출하는 레포지토리를 거쳐 다시 컨트롤러로 돌아오는 동안 유지되어야 한다. 그리고 레벨은 하나씩 증가되어야 한다. 이를 해결하는 가장 간단한 방법은 무엇일까? 파라미터 전달이다. 

로그 추적기 V2 - 파라미터로 동기화 개발

트랜잭션 ID와 메서드 호출의 깊이를 표현하는 가장 단순한 방법은 첫 로그에서 사용한 트랜잭션 ID와 level을 다음 로그에 넘겨주면 된다. 현재 로그의 상태 정보인 트랜잭션 ID와 level은 TraceId에 포함되어 있다. 따라서 TraceId를 다음 로그에 넘겨주면 된다. 이 기능을 추가한 HelloTraceV2를 개발해보자.

HelloTraceV2

package cwchoiit.springadvanced.trace.hellotrace;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@Slf4j
@Component
public class HelloTraceV2 {

    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 startTime = System.currentTimeMillis();

        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTime, message);
    }

    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
        TraceId nextId = beforeTraceId.createNextId();
        long startTime = System.currentTimeMillis();

        log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
        return new TraceStatus(nextId, startTime, message);
    }

    public void end(TraceStatus status) {
        complete(status, null);
    }

    public void exception(TraceStatus status, Throwable ex) {
        complete(status, ex);
    }

    private void complete(TraceStatus status, Throwable ex) {
        long stopTime = System.currentTimeMillis();
        long resultTime = stopTime - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();

        if (ex == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTime);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTime, ex.getMessage());
        }
    }

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

• 기존 코드와 모두 동일한데 딱 하나의 추가된 메서드가 있다.

public TraceStatus beginSync(TraceId beforeTraceId, String message) {
    TraceId nextId = beforeTraceId.createNextId();
    long startTime = System.currentTimeMillis();

    log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
    return new TraceStatus(nextId, startTime, message);
}

• 이전 TraceId를 전달받는 beginSync 메서드. begin()과 차이점은 새로 TraceId를 만들어서 level 0을 가지는 TraceId가 아닌, 기존의 TraceId를 받아 createNextId() 메서드를 호출해서 현재 레벨에 + 1 한 TraceId를 받는것이다.

로그 추적기 V2 - 적용

OrderControllerV2

package cwchoiit.springadvanced.app.v2;

import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV1;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

    @GetMapping("/v2/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderControllerV1.request(String itemId)");
            orderService.orderItem(status.getTraceId(), itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

• TraceStatus status = trace.begin()에서 반환 받은 TraceStatus에는 트랜잭션 ID와 level 정보가 있는 TraceId가 있다. orderSerivce.orderItem()을 호출할 때 이 TraceId를 파라미터로 전달한다. 

OrderServiceV2

package cwchoiit.springadvanced.app.v2;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(TraceId traceId, String itemId) {
        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderServiceV1.orderItem(String itemId)");
            orderRepository.save(status.getTraceId(), itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

• orderItem()은 파라미터로 전달 받은 traceId를 사용해서 trace.beginSync()를 실행한다. beginSync()는 내부에서 다음 traceId를 생성하면서 트랜잭션 ID는 유지하고 level은 하나 증가시킨다.
• beginSync()가 반환한 새로운 TraceStatus를 orderRepository.save()를 호출하면서 파라미터로 전달한다.

OrderRepositoryV2

package cwchoiit.springadvanced.app.v2;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {

    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {
        TraceStatus status = null;
        try {
            status = trace.beginSync(traceId, "OrderRepositoryV1.save(String itemId)");
            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 ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

정상 실행 로그

 [c80f5dbb] OrderController.request()
 [c80f5dbb] |-->OrderService.orderItem()
 [c80f5dbb] |   |-->OrderRepository.save()
 [c80f5dbb] |   |<--OrderRepository.save() time=1005ms
 [c80f5dbb] |<--OrderService.orderItem() time=1014ms
 [c80f5dbb] OrderController.request() time=1017ms

• 이제야 좀 이쁜 로그가 찍히기 시작한다. 그런데 이 짓을 위해 관련 메서드의 모든 파라미터를 수정하는 작업부터 시작해서, 로그를 처음 시작할 때는 begin()을 호출하고 처음이 아닐때는 beginSync()를 호출해야 한다. 이런 짓거리를 어떻게 할까? 안될것 같다. 더 좋은 대안이 필요하다.

필드 동기화 - 개발

앞서 로그 추적기를 만들면서 다음 로그를 출력할 때 트랜잭션 ID와 level을 동기화하는 문제가 있었다. 이 문제를 해결하기 위해 TraceId를 파라미터로 넘기도록 구현했다. 이렇게해서 동기화는 성공했지만, 로그를 출력하는 모든 메서드에 TraceId 파라미터를 추가해야 하는 문제가 발생했다. TraceId를 파라미터로 넘기지 않고 이 문제를 해결할 수 있는 방법은 없을까?

이런 문제를 해결할 목적으로 새로운 로그 추적기를 만들어보자. 이제 프로토타입 버전이 아닌 정식 버전으로 제대로 개발해보자. 향후 다양한 구현체로 변경할 수 있도록 LogTrace 인터페이스를 먼저 만들고 구현해보자.

LogTrace

package cwchoiit.springadvanced.trace.logtrace;

import cwchoiit.springadvanced.trace.TraceStatus;

public interface LogTrace {
    TraceStatus begin(String message);
    void end(TraceStatus status);
    void exception(TraceStatus status, Throwable throwable);
}

• LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()을 정의했다. 이제 파라미터를 넘기지 않고 TraceId를 동기화할 수 있는 FieldLogTrace 구현체를 만들어보자.

FieldLogTrace

package cwchoiit.springadvanced.trace.logtrace;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@Slf4j
public class FieldLogTrace implements LogTrace {

    private static final String START_PREFIX = "--->";
    private static final String COMPLETE_PREFIX = "<---";
    private static final String EX_PREFIX = "<X--";

    private TraceId traceIdHolder; // traceId 동기화

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder;
        long startTime = System.currentTimeMillis();

        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTime, message);
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }

    @Override
    public void exception(TraceStatus status, Throwable throwable) {
        complete(status, throwable);
    }

    private void complete(TraceStatus status, Throwable ex) {
        long stopTime = System.currentTimeMillis();
        long resultTime = stopTime - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();

        if (ex == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTime);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTime, ex.getMessage());
        }

        releaseTraceId();
    }

    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

    private void releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null;
        } else {
            traceIdHolder = traceIdHolder.createPrevId();
        }
    }

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

• FieldLogTrace는 기존에 만들었던 HelloTraceV2와 거의 같은 기능을 한다. 
• TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceIdHolder 필드를 사용하도록 변경되었다.
• 이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHolder에 저장된다.
• 여기서 중요한 부분은 로그를 시작할 때 호출하는 syncTraceId()와 로그를 종료할 때 호출하는 releaseTraceId()이다. 

private void syncTraceId() {
    if (traceIdHolder == null) {
        traceIdHolder = new TraceId();
    } else {
        traceIdHolder = traceIdHolder.createNextId();
    }
}

• TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가시킨다.
• 최초 호출이면 TraceId를 새로 만든다.
• 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level도 하나 증가한다.
• 결과를 traceIdHolder에 보관한다.

private void releaseTraceId() {
    if (traceIdHolder.isFirstLevel()) {
        traceIdHolder = null;
    } else {
        traceIdHolder = traceIdHolder.createPrevId();
    }
}

• 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소해야 한다.
• releaseTraceId()는 level을 하나 감소한다.
• 만약, 최초 호출(level == 0)이면, 내부에서 관리하는 traceId를 제거한다.
• 그러니까, 아래와 같은 흐름이라고 생각하면 되겠다.

[c80f5dbb] OrderController.request() //syncTraceId(): 최초 호출 level=0
[c80f5dbb] |-->OrderService.orderItem() //syncTraceId(): 직전 로그 있음 level=1 증가
[c80f5dbb] | |-->OrderRepository.save() //syncTraceId(): 직전 로그 있음 level=2 증가
[c80f5dbb] |   |<--OrderRepository.save() time=1005ms //releaseTraceId(): level=2->1 감소
[c80f5dbb] |<--OrderService.orderItem() time=1014ms level=1->0 감소
[c80f5dbb] OrderController.request() time=1017ms level==0, traceId 제거

필드 동기화 - 적용

지금까지 만든 FieldLogTrace를 애플리케이션에 적용해보자. 

LogTrace 스프링 빈 등록

FieldLogTrace를 수동으로 스프링 빈으로 등록하자. 수동으로 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있다.

LogTraceConfig

package cwchoiit.springadvanced;

import cwchoiit.springadvanced.trace.logtrace.FieldLogTrace;
import cwchoiit.springadvanced.trace.logtrace.LogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace() {
        return new FieldLogTrace();
    }
}

V2 → V3 변경

이전에 사용했던 V2 버전을 V3로 모두 변경하자.

OrderControllerV3

package cwchoiit.springadvanced.app.v3;

import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import cwchoiit.springadvanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {

    private final OrderServiceV3 orderService;
    private final LogTrace trace;

    @GetMapping("/v3/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderControllerV1.request(String itemId)");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

OrderServiceV3

package cwchoiit.springadvanced.app.v3;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import cwchoiit.springadvanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@Service
@RequiredArgsConstructor
public class OrderServiceV3 {

    private final OrderRepositoryV3 orderRepository;
    private final LogTrace trace;

    public void orderItem(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderServiceV1.orderItem(String itemId)");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

OrderRepositoryV3

package cwchoiit.springadvanced.app.v3;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import cwchoiit.springadvanced.trace.hellotrace.HelloTraceV2;
import cwchoiit.springadvanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {

    private final LogTrace trace;

    public void save(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepositoryV1.save(String itemId)");
            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 ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

이렇게 만들어 둔 상태에서 아래와 같이 실행해보자.

실행 결과

### OrderControllerV3.request
GET http://localhost:8080/v3/request?itemId=Good

[86537cdd] OrderControllerV1.request(String itemId)
[86537cdd] |--->OrderServiceV1.orderItem(String itemId)
[86537cdd] |    |--->OrderRepositoryV1.save(String itemId)
[86537cdd] |    |<---OrderRepositoryV1.save(String itemId) time=1001ms
[86537cdd] |<---OrderServiceV1.orderItem(String itemId) time=1002ms
[86537cdd] OrderControllerV1.request(String itemId) time=1002ms

• 잘 되는것 같다. 이제야 좀 그래도 가져다가 쓸 만한 코드를 작성한 것 같은데.. 과연 아무 문제가 없을까? 

필드 동기화 - 동시성 문제

잘 만든 로그 추적기를 실제 서비스에 배포했다 가정해보자. 테스트 할 때는 문제가 없는 것 처럼 보였다. 사실 직전에 만든 FieldLogTrace는 심각한 동시성 문제를 가지고 있다. 동시성 문제를 확인하려면 다음과 같이 동시에 여러번 호출하면 된다.

동시성 문제 확인 - 1초에 2번 실행

### OrderControllerV3.request
GET http://localhost:8080/v3/request?itemId=Good

[f0854d53] OrderControllerV1.request(String itemId)
[f0854d53] |--->OrderServiceV1.orderItem(String itemId)
[f0854d53] |    |--->OrderRepositoryV1.save(String itemId)
[f0854d53] |    |    |--->OrderControllerV1.request(String itemId)
[f0854d53] |    |    |    |--->OrderServiceV1.orderItem(String itemId)
[f0854d53] |    |    |    |    |--->OrderRepositoryV1.save(String itemId)
[f0854d53] |    |<---OrderRepositoryV1.save(String itemId) time=1001ms
[f0854d53] |<---OrderServiceV1.orderItem(String itemId) time=1002ms
[f0854d53] OrderControllerV1.request(String itemId) time=1002ms
[f0854d53] |    |    |    |    |<---OrderRepositoryV1.save(String itemId) time=1001ms
[f0854d53] |    |    |    |<---OrderServiceV1.orderItem(String itemId) time=1001ms
[f0854d53] |    |    |<---OrderControllerV1.request(String itemId) time=1001ms

• 동시에 여러 사용자가 요청하면, 여러 쓰레드가 동시에 애플리케이션 로직을 호출하게 된다. 따라서 로그는 이렇게 이상하게 찍혀버린다. 물론 동시에 여러 요청이 들어오면 로그가 섞여 찍힐 순 있지만 위처럼 트랜잭션 ID가 동일해서는 안된다. 하지만 서로 다른 요청이 같은 트랜잭션 ID를 가지고 있다.

동시성 문제

왜 이런 문제가 발생할까? 바로 FieldLogTrace는 싱글톤으로 등록된 스프링 빈이고, 이 객체의 인스턴스가 애플리케이션에 딱 하나만 존재하는데 이렇게 하나만 존재하는 인스턴스의 전역 변수(필드)인 traceIdHolder에 여러 쓰레드가 동시에 접근하기 때문이다. 동시에 접근하더라도 읽기만 한다면 동시성 문제는 발생하지 않는다. 그러나 지금은 읽기만 하는게 아니라 쓰기를 하고 있기 때문에 동시성 문제가 발생한다.

동시성 문제가 발생할 수 있는 환경

• 지역 변수가 아닌 전역 변수 또는 클래스 멤버(변수)
• 읽기 작업만 일어나는 게 아니라 쓰기 작업이 가해지는 변수

참고로, 지역 변수(예를 들면, 메서드안에서 새로 만들어지는 변수와 같은)는 동시성 문제가 발생하지 않는다. 너무 기본적인 내용이지만 한번 더 리마인드하면 좋으니까! 왜 동시성 문제가 발생하지 않냐면 지역변수는 스레드 별로 새로 만들어진다. 스택 영역에 메서드를 호출한 순서대로 스택 프레임이 쌓이고 그 스택 프레임에는 메서드 안에서 만들어야 하는 지역변수도 담고 있다. 

다음 코드로 동시성 문제에 대한 예시를 살펴보자.

FieldService

package com.example.advanced.trace.threadlocal.code;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class FieldService {

    private String nameStore;

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore);

        nameStore = name;

        sleep(1000);

        log.info("조회 nameStore={}", nameStore);

        return nameStore;
    }

    private void sleep(int ms) {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• 위 서비스 코드를 보면, nameStore라는 필드가 있고, logic() 메소드가 있다. 이 메소드에서 파라미터로 name을 받으면 그 name을 nameStore에 저장하는 간단한 코드이다. 저장한 후 1초 뒤에 저장된 값을 조회하는 로그가 있고 로직은 종료된다.

FieldServiceTest

package com.example.advanced.trace.threadlocal;

import com.example.advanced.trace.threadlocal.code.FieldService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class FieldServiceTest {

    private FieldService fieldService = new FieldService();

    @Test
    void field() {
        log.info("main start");

        Runnable userA = () -> {
            fieldService.logic("userA");
        };

        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");

        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(2000);
        threadB.start();
        sleep(3000);

        log.info("main exit");
    }

    private void sleep(int ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

• 독립적인 Thread 두 개를 생성한다. 생성한 Thread가 실행하는 코드는 new로 새로 만든 인스턴스인 FieldService의 logic() 메소드이다. 이 두 개의 쓰레드를 실행할 때 threadA를 실행한 후 2초 뒤 threadB를 실행한다.

지금 위 코드로는 동시성 문제는 발생하지 않는다. 왜냐하면 FieldService.logic() 메소드는 nameStore에 저장한 뒤 1초뒤에 조회를 하는데 threadA와 threadB의 각 실행 사이의 간격이 2초이기 때문이다. 실행해보면 다음과 같은 결과를 볼 수 있다.

09:03:03.389 [Test worker] INFO com.example.advanced.trace.threadlocal.FieldServiceTest -- main start
09:03:03.395 [thread-A] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 저장 name=userA -> nameStore=null
09:03:04.402 [thread-A] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userA
09:03:05.397 [thread-B] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 저장 name=userB -> nameStore=userA
09:03:06.403 [thread-B] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userB
09:03:08.397 [Test worker] INFO com.example.advanced.trace.threadlocal.FieldServiceTest -- main exit

• 문제 없이 본인이 저장한 값으로 조회되는 것을 확인할 수 있다.

그러나, 여기서 threadA와 threadB 실행 사이의 간격을 0.1초로 변경한다면 동시성 문제가 발생한다. 

왜 그럴까? 이유는 필드에 값을 저장하고 조회하기까지 걸리는 시간은 1초인데 새로운 쓰레드가 동일한 필드에 접근하는 시간이 0.1초이기 때문이다. 

....
        threadA.start();
        sleep(100); // 동시성 문제 발생 원인 코드
        threadB.start();
        sleep(3000);
....

이렇게 코드를 변경하고 실행해보자. 예상 못했던 결과가 도출된다.

09:06:46.886 [Test worker] INFO com.example.advanced.trace.threadlocal.FieldServiceTest -- main start
09:06:46.891 [thread-A] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 저장 name=userA -> nameStore=null
09:06:46.992 [thread-B] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 저장 name=userB -> nameStore=userA
09:06:47.897 [thread-A] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userB
09:06:47.993 [thread-B] INFO com.example.advanced.trace.threadlocal.code.FieldService -- 조회 nameStore=userB
09:06:49.993 [Test worker] INFO com.example.advanced.trace.threadlocal.FieldServiceTest -- main exit

• 결과는 두 쓰레드 모두 조회값이 "userB"로 출력된다. 이유는 "userA"라는 값을 저장한 후 1초뒤 값을 조회하는 코드가 실행되는데 조회하기 전 다른 쓰레드에서 "userB"라는 값을 저장했기 때문이다. 이게 '동시성 문제'이다. 이런 동시성 문제를 해결하기 위해 어떠한 조치를 취할 수 있을까? 방법은 다양하겠지만 여기서 설명하고자 하는 건 ThreadLocal이다.

ThreadLocal

ThreadLocal은 해당 쓰레드만 접근할 수 있는 특별한 저장소를 말한다. 즉, 찜질방에서 생김새와 모양이 완전히 똑같은 여러개의 락커가 있지만 그 락커마다의 주인이 딱 한명인 것처럼 말이다. 그럼 그림을 통해 일반적인 변수 필드와 쓰레드 로컬을 사용한 변수에 어떤 차이가 있는지 확인해보자.

일반적인 변수 필드

여러 쓰레드가 같은 인스턴스의 필드에 접근하면 처음 쓰레드가 보관한 데이터가 사라질 수 있다.

쓰레드 로컬

쓰레드 로컬을 사용하면 각 쓰레드마다 별도의 내부 저장소를 제공한다. 따라서 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제가 없다.

• 쓰레드 로컬을 통해서 데이터를 조회할 때도 thread-A가 조회하면 쓰레드 로컬은 thread-A 전용 보관소에서 "userA" 데이터를 반환해준다. 물론, thread-B가 조회하면 thread-B 전용 보관소에서 "userB" 데이터를 반환해준다.
• 자바는 언어차원에서 쓰레드 로컬을 지원하기 위한 `java.lang.ThreadLocal` 클래스를 제공한다.

이 쓰레드 로컬을 코드로 좀 더 깊이 있게 이해해보자.

ThreadLocalService

package com.example.advanced.trace.threadlocal.code;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class ThreadLocalService {

    private final ThreadLocal<String> nameStore = new ThreadLocal<>();

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore.get());

        nameStore.set(name);

        sleep(1000);

        log.info("조회 nameStore={}", nameStore.get());

        return nameStore.get();
    }

    private void sleep(int ms) {
        try {
            Thread.sleep(1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

• 기존 FieldService에서 ThreadLocalService로 변경되면서 바뀌는 부분은 nameStore가 ThreadLocal 타입이라는 점이다. 그리고 이 ThreadLocal은 값을 세팅하고 조회하기 위해 .set(), .get()을 사용한다.

ThreadLocalServiceTest

package com.example.advanced.trace.threadlocal;

import com.example.advanced.trace.threadlocal.code.FieldService;
import com.example.advanced.trace.threadlocal.code.ThreadLocalService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class ThreadLocalServiceTest {

    private ThreadLocalService service = new ThreadLocalService();

    @Test
    void field() {
        log.info("main start");

        Runnable userA = () -> {
            service.logic("userA");
        };

        Runnable userB = () -> {
            service.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");

        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(100);
        threadB.start();
        sleep(3000);

        log.info("main exit");
    }

    private void sleep(int ms) {
        try {
            Thread.sleep(ms);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }
}

• FieldServiceTest에서 ThreadLocalServiceTest로 변경했다. 바뀌는 부분은 서비스가 ThreadLocalService라는 점. 그리고 기존 코드에서 동시성 이슈를 발생했던 sleep(100)을 그대로 두고 실행해도 동시성 문제는 발생하지 않는다. 결과를 보자.

09:13:41.235 [Test worker] INFO com.example.advanced.trace.threadlocal.ThreadLocalServiceTest -- main start
09:13:41.240 [thread-A] INFO com.example.advanced.trace.threadlocal.code.ThreadLocalService -- 저장 name=userA -> nameStore=null
09:13:41.340 [thread-B] INFO com.example.advanced.trace.threadlocal.code.ThreadLocalService -- 저장 name=userB -> nameStore=null
09:13:42.244 [thread-A] INFO com.example.advanced.trace.threadlocal.code.ThreadLocalService -- 조회 nameStore=userA
09:13:42.345 [thread-B] INFO com.example.advanced.trace.threadlocal.code.ThreadLocalService -- 조회 nameStore=userB
09:13:44.344 [Test worker] INFO com.example.advanced.trace.threadlocal.ThreadLocalServiceTest -- main exit

서로 다른 쓰레드가 모두 독립적인 ThreadLocal 필드를 가지기 때문에 최초 조회 시 모두 값은 null이다. 그리고 1초 뒤 조회해도 본인이 저장한 값으로 조회된다.ThreadLocal을 이용해서 동시성 문제를 해결했다. 

ThreadLocal 사용 시 주의점

쓰레드 로컬의 값을 사용 후 제거하지 않고 그냥 두면 WAS(톰캣)처럼 쓰레드 풀을 사용하는 경우에 심각한 문제가 발생할 수 있다. 다음 예시를 통해서 알아보자.

• 사용자A가 저장 관련 HTTP 요청을 했다.
• WAS는 쓰레드 풀에서 쓰레드 하나를 조회한다.
• 쓰레드(thread-A)가 할당되었다.
• thread-A는 사용자A의 데이터를 쓰레드 로컬에 저장한다.
• 쓰레드 로컬의 thread-A 전용 보관소에 사용자A 데이터를 보관한다.

사용자A 저장 요청 종료

• 사용자A의 HTTP 응답이 끝난다.
• WAS는 사용이 끝난 thread-A를 쓰레드 풀에 반환한다. 쓰레드를 생성하는 비용은 비싸기 때문에 쓰레드를 제거하지 않고, 보통 쓰레드 풀을 통해서 쓰레드를 재사용한다.
• thread-A는 쓰레드 풀에 아직 살아있다. 따라서, 쓰레드 로컬의 thread-A 전용 보관소에 사용자A 데이터도 함께 살아있게 된다.

• 사용자B가 조회를 위한 새로운 HTTP 요청을 한다.
• WAS는 쓰레드 풀에서 쓰레드 하나를 조회한다.
• 하필! 쓰레드(thread-A)가 할당되었다. (물론 다른 쓰레드가 할당될 수 있다 운이 좋다면!)
• 이번에는 조회하는 요청이다. thread-A는 쓰레드 로컬에서 데이터를 조회한다.
• 쓰레드 로컬은 thread-A 전용 보관소에 있는 사용자A값을 반환한다.
• 결과적으로 사용자A의 값이 사용자B에게 반환된다.

결과적으로, 사용자B는 사용자A의 데이터를 확인하게 되는 매우 심각한 문제가 발생하게 된다. 이런 문제를 예방하려면 사용자A의 요청이 끝날 때, 쓰레드 로컬의 값을 ThreadLocal.remove()를 호출해서 반드시! 반드시 제거해야 한다. 쓰레드 로컬을 사용할 때는 이 부분을 매우매우 중요하게 꼭! 기억하자.

쓰레드 로컬 동기화 - 개발

FieldLogTrace에서 발생했던 동시성 문제를 ThreadLocal로 해결해보자. TraceId traceIdHolder 필드를 쓰레드 로컬을 사용하도록 ThreadLocal<TraceId> traceIdHolder로 변경하면 된다.

ThreadLocalLogTrace

package cwchoiit.springadvanced.trace.logtrace;

import cwchoiit.springadvanced.trace.TraceId;
import cwchoiit.springadvanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@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 동기화

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder.get();
        long startTime = System.currentTimeMillis();

        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTime, message);
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }

    @Override
    public void exception(TraceStatus status, Throwable throwable) {
        complete(status, throwable);
    }

    private void complete(TraceStatus status, Throwable ex) {
        long stopTime = System.currentTimeMillis();
        long resultTime = stopTime - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();

        if (ex == null) {
            log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTime);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTime, ex.getMessage());
        }

        releaseTraceId();
    }

    private void syncTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId == null) {
            traceIdHolder.set(new TraceId());
        } else {
            traceIdHolder.set(traceId.createNextId());
        }
    }

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove();
        } else {
            traceIdHolder.set(traceId.createPrevId());
        }
    }

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

• traceIdHolder가 필드에서 ThreadLocal로 변경되었다. 따라서, 값을 저장할 때는 set(...)을 사용하고, 값을 조회할 때는 get()을 사용한다. 
• 이 코드에서는 위에서 말했던 주의점인 다 사용한 다음에는 ThreadLocal.remove()를 호출하는 코드가 반영되어 있다.

private void releaseTraceId() {
    TraceId traceId = traceIdHolder.get();
    if (traceId.isFirstLevel()) {
        traceIdHolder.remove();
    } else {
        traceIdHolder.set(traceId.createPrevId());
    }
}

쓰레드 로컬 동기화 - 적용

LogTraceConfig - 수정

package cwchoiit.springadvanced;

import cwchoiit.springadvanced.trace.logtrace.LogTrace;
import cwchoiit.springadvanced.trace.logtrace.ThreadLocalLogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace() {
        return new ThreadLocalLogTrace();
    }
}

• 동시성 문제가 있는 FieldLogTrace 대신에 문제를 해결한 ThreadLocalLogTrace를 스프링 빈으로 등록하자.
• 이게 바로 스프링의 막강한 장점인, 구현체만 갈아끼우면 되는 DI이다. 클라이언트 코드는 손 댈 게 없다. 왜냐? 클라이언트 코드는 구현체에 직접적으로 의존하는게 아니라 구현체의 기준인 인터페이스에만 의존하고 있기 때문에!
• 이제 연속으로도 호출해보고 막 해보자 막!

실행 결과

[nio-8080-exec-1] [ce909512] OrderControllerV1.request(String itemId)
[nio-8080-exec-1] [ce909512] |--->OrderServiceV1.orderItem(String itemId)
[nio-8080-exec-1] [ce909512] |    |--->OrderRepositoryV1.save(String itemId)
[nio-8080-exec-2] [bc43b1df] OrderControllerV1.request(String itemId)
[nio-8080-exec-2] [bc43b1df] |--->OrderServiceV1.orderItem(String itemId)
[nio-8080-exec-2] [bc43b1df] |    |--->OrderRepositoryV1.save(String itemId)
[nio-8080-exec-1] [ce909512] |    |<---OrderRepositoryV1.save(String itemId) time=1001ms
[nio-8080-exec-1] [ce909512] |<---OrderServiceV1.orderItem(String itemId) time=1002ms
[nio-8080-exec-1] [ce909512] OrderControllerV1.request(String itemId) time=1003ms
[nio-8080-exec-2] [bc43b1df] |    |<---OrderRepositoryV1.save(String itemId) time=1000ms
[nio-8080-exec-2] [bc43b1df] |<---OrderServiceV1.orderItem(String itemId) time=1001ms
[nio-8080-exec-2] [bc43b1df] OrderControllerV1.request(String itemId) time=1001ms

• 로그가 출력되는 순서는 살짝 뒤죽박죽이지만, 이제는 트랜잭션 ID도 명확하게 분리되어 있고, 레벨도 아무런 문제없이 잘 표현된다. 이렇게 되면 요청당 어떤 흐름이 진행되는지 명확하게 구분하고 확인할 수 있다.