[1편]운영 로그에서 비동기 구간만 traceId가 빠졌다: MDC와 TaskDecorator로 해결하기

요청마다 traceId를 MDC에 심어 로그를 추적하고 있었는데, CompletableFuture.supplyAsync 구간의 로그에서만 traceId가 빠지는 문제를 겪었습니다. 원인과 해결 방법을 정리합니다.

TL;DR

• MDC는 ThreadLocal 기반이라, 스레드가 바뀌는 supplyAsync 구간에서는 traceId가 사라집니다.
• 해결의 핵심은 작업을 제출하는 스레드에서 복사하고, 실행하는 스레드에서 주입한 뒤, 끝나면 정리하는 것입니다.
• ThreadPoolTaskExecutor에 TaskDecorator를 적용하고, supplyAsync와 thenApplyAsync에 executor를 반드시 지정하면 됩니다.

---

1. 상황

필터에서 traceId를 MDC에 넣고, logback 패턴(%X{traceId:-SYSTEM}, traceId가 없으면 SYSTEM 표시)으로 모든 로그에 출력하고 있었습니다.

// TraceIdFilter.doFilterInternal 핵심부
MDC.put("traceId", traceId);
try {
    filterChain.doFilter(request, response);
} finally {
    MDC.remove("traceId");   // 스레드 재사용 대비
}

그런데 비동기 메소드의 로그는 전부 [SYSTEM]으로 찍혔습니다.

public CompletableFuture<Result> sendEmail(Map<String, Object> param) {
    return CompletableFuture.supplyAsync(() -> {
        log.info("메일 발송 시작");   // → [SYSTEM] 으로 출력됨
        // ...
    });
}

---

2. 원인

MDC는 ThreadLocal 기반이라 스레드가 바뀌면 값이 따라가지 않습니다. 요청을 처리하는 스레드를 A, 비동기 작업을 실행하는 스레드를 A-1이라고 하겠습니다.

[요청 스레드 A]                              [비동기 스레드 A-1]
  MDC.put("traceId", "a1b2...")
  └ supplyAsync(() -> {...})  ───────────►  log.info(...)
                                             MDC 비어 있음 → [SYSTEM]
  finally { MDC.remove }

동기와 비교하면 차이가 분명합니다.

	동기	비동기
실행 스레드	A (동일)	A-1 (별개)
MDC	그대로 유지	A-1에는 없음
요청 종료 후 로직 실행 가능성	없음	있음 (큐 대기, 장시간 작업)

더 까다로운 점은 A가 먼저 끝날 수 있다는 것입니다. 작업이 큐에서 대기하는 사이 A의 요청이 끝나 MDC가 지워지고, A-1에서는 A의 값을 읽을 방법이 없습니다. 따라서 A가 살아 있는 시점에 값을 복사해 두어야 합니다.

---

3. 비동기는 어디서, 어떻게 실행되는가

• supplyAsync(() -> {...})처럼 executor를 생략하면 JVM 공용 풀인 ForkJoinPool.commonPool()에서 실행됩니다. 이 풀은 크기, 거부 정책, 컨텍스트 전달을 제어할 수 없습니다.
• 직접 만든 ThreadPoolTaskExecutor를 지정하면 아래 순서로 처리됩니다. 스레드를 매번 새로 만드는 것이 아니라, 풀에서 빌려 쓰고 반납해서 재사용합니다.

작업 제출 (제출한 스레드 A는 기다리지 않고 바로 반환)
  ├─ 스레드 수 < corePoolSize      → 새 스레드로 즉시 실행
  ├─ 큐에 여유 있음(queueCapacity) → 큐에서 대기, 빈 스레드가 꺼내 실행
  ├─ 스레드 수 < maxPoolSize       → 새 스레드로 실행 (큐가 가득 찬 뒤에야)
  └─ 모두 꽉 참                    → RejectedExecutionException (제출한 스레드에서 발생)

queueCapacity 기본값은 Integer.MAX_VALUE입니다. 설정하지 않으면 큐가 가득 차지 않아 스레드가 core 수를 넘어 늘어나지 않고, 거부도 발생하지 않습니다.

자주 헷갈리는 질문

Q. supplyAsync를 호출할 때마다 스레드가 새로 생성되나요?
아닙니다. 정해진 크기의 풀에서 스레드를 하나 빌려 쓰고, 끝나면 반납해서 재사용합니다. 새 스레드가 만들어지는 경우는 core 수에 도달하기 전이거나, 큐가 가득 찬 뒤 max까지 늘어날 때뿐입니다. 풀의 크기는 하나의 숫자가 아니라 corePoolSize(기본 유지 수), queueCapacity(대기 큐), maxPoolSize(상한) 세 값으로 정해집니다.

Q. 호출하면 바로 실행되나요, 큐에서 기다리나요?
풀 상태에 따라 다릅니다. 놀고 있는 스레드가 있거나 core 미만이면 제출 즉시 실행되고, 모두 사용 중일 때만 큐에서 기다렸다가 스레드가 비면 실행됩니다. 어느 쪽이든 supplyAsync는 작업을 제출만 하고 CompletableFuture를 바로 반환하므로, A 스레드는 완료를 기다리지 않고 자기 흐름을 이어갑니다.

Q. taskExecutor를 지정하면 별도의 스레드를 새로 선언하는 건가요?
supplyAsync는 어떤 방식이든 요청 스레드와 다른 스레드에서 실행됩니다. 차이는 그 스레드 풀을 누가 소유하느냐입니다. executor를 생략하면 JVM 공용 commonPool을 쓰고, taskExecutor를 지정하면 우리가 설정한 풀을 씁니다. 이미 빈으로 선언된 풀을 쓰는 것이라면 풀이 새로 생기지 않고, 지금 commonPool로 가던 작업이 그 풀로 옮겨 가는 것입니다.

---

4. 해결: 제출 시점에 복사, 실행 직전에 주입

A 스레드 (요청)                              A-1 스레드 (풀)
 MDC={traceId:a1b2}
 supplyAsync(..., executor) 호출
   ├─ [제출 시점] traceId 복사
   ├─ 큐에 작업 등록 ───────────────────►  (큐에서 대기할 수도 있음)
 A는 자기 흐름대로 진행/종료                [실행 직전] 복사해 둔 값을 MDC에 주입
                                           로직 실행 → 로그에 [a1b2]
                                           종료 시 MDC 정리

순서로 정리하면 다음과 같습니다.

1. A 스레드: TraceIdFilter가 MDC에 traceId 저장
2. A 스레드: supplyAsync(..., executor) 호출(제출) → 이 순간 traceId를 복사
3. A-1 스레드: 실행 직전에 복사해 둔 값을 자기 MDC에 주입
4. A-1 스레드: 로직 실행 → 로그에 같은 traceId 출력
5. A-1 스레드: 종료 시 MDC 정리

왜 실행 시점이 아니라 제출 시점에 복사할까요

A-1이 실행되는 시점에는 A가 이미 종료되어 MDC가 지워졌을 수 있습니다. 풀이 바빠서 큐에서 대기하는 동안 A가 먼저 끝나는 경우입니다. 그래서 A가 살아 있는 제출 시점에 값을 복사해 두고, A-1은 그 복사본을 꺼내 씁니다.

traceId가 "공유"되는 것이 아니라 값이 복사되어 전달됩니다. 종료 시 정리가 필수인 이유는 풀 스레드가 재사용되기 때문입니다. 정리하지 않으면 다른 요청의 traceId가 찍히는데, 이는 traceId가 없는 것보다 더 위험합니다.

---

5. 구현

TaskDecorator + executor 지정 (권장)

TaskDecorator는 작업이 제출될 때 Runnable을 감싸는 훅입니다. 복사, 주입, 정리를 한 곳에서 처리합니다.

public class MdcTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> context = MDC.getCopyOfContextMap();   // 제출 스레드(A)에서 복사
        return () -> {
            if (context != null) MDC.setContextMap(context);       // 풀 스레드(A-1)에서 주입
            try {
                runnable.run();
            } finally {
                MDC.clear();                                       // 재사용 대비 정리
            }
        };
    }
}

@Bean(name = "taskExecutor")
public ThreadPoolTaskExecutor taskExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(5);
    executor.setMaxPoolSize(10);
    executor.setQueueCapacity(100);
    executor.setThreadNamePrefix("async-");
    executor.setTaskDecorator(new MdcTaskDecorator());
    executor.initialize();
    return executor;
}

호출부에서는 풀만 지정하면 됩니다.

CompletableFuture.supplyAsync(() -> { /* ... */ }, taskExecutor);   // → [a1b2...] 로 출력

주의할 점

• commonPool에서 직접 만든 풀로 실행 풀이 바뀝니다. 큐와 max가 모두 차면 제출한 스레드에서 RejectedExecutionException이 발생하므로, 거부 정책(CallerRunsPolicy 등)과 풀 크기를 검토해야 합니다.
• 장시간 작업과 풀을 공유하면 밀릴 수 있으니, 부담되면 용도별로 풀을 분리하세요.

함정: 체이닝 단계에도 executor를 넘겨야 합니다. *Async 단계에서 executor를 생략하면 그 단계는 다시 commonPool에서 실행되어 MDC가 또 사라집니다.

CompletableFuture
    .supplyAsync(() -> findTarget(), taskExecutor)
    .thenApplyAsync(target -> send(target))                 // ✗ commonPool → traceId 유실
    .thenApplyAsync(result -> save(result), taskExecutor);  // ✓ executor 지정

다른 방안과 비교

방안	내용	누락 위험	비고
A. TaskDecorator	풀 설정 한 곳에서 처리	낮음	풀 변경, 거부 정책 확인 필요
B. 수동 복사	supplyAsync 안에서 직접 MDC.getCopyOfContextMap() / setContextMap()	높음	풀이 바뀌지 않음, 지점이 적을 때 임시 조치로 적합
C. context-propagation	io.micrometer:context-propagation 의존성 추가	낮음	MDC만 전달하려는 목적에는 과함, Boot 자동 구성 범위는 사용 버전 문서로 확인

---

6. 검증

로그로 확인: 패턴에 %thread를 넣어 스레드가 바뀌는 것을 확인합니다.

<property name="LOG_PATTERN"
          value="[%d{HH:mm:ss.SSS}] [%thread] [%X{traceId:-SYSTEM}] %logger{20} - %msg%n"/>

적용 전에는 비동기 스레드의 traceId가 SYSTEM이고, 적용 후에는 요청 스레드와 같은 값이 나와야 합니다. 아래는 이해를 돕기 위한 예시 로그입니다.

Before: 비동기 스레드에서 traceId 유실

[10:21:03.412] [http-nio-8080-exec-3]            [a1b2c3d4e5f6a7b8] c.e.MailController - 메일 발송 요청
[10:21:03.415] [ForkJoinPool.commonPool-worker-1] [SYSTEM]           c.e.MailService    - 메일 발송 시작
[10:21:03.980] [ForkJoinPool.commonPool-worker-1] [SYSTEM]           c.e.MailService    - 메일 발송 완료

After: TaskDecorator + executor 지정 후

[10:21:03.412] [http-nio-8080-exec-3] [a1b2c3d4e5f6a7b8] c.e.MailController - 메일 발송 요청
[10:21:03.415] [async-1]              [a1b2c3d4e5f6a7b8] c.e.MailService    - 메일 발송 시작
[10:21:03.980] [async-1]              [a1b2c3d4e5f6a7b8] c.e.MailService    - 메일 발송 완료

스레드 이름은 http-nio-...에서 async-1로 바뀌지만, traceId는 요청부터 비동기 구간까지 같은 값으로 이어집니다.

테스트로 확인: JUnit 5와 AssertJ 기준입니다.

class MdcTaskDecoratorTest {

    private ThreadPoolTaskExecutor executor;

    @BeforeEach
    void setUp() {
        executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(1);          // 같은 스레드가 재사용되도록 1개로 제한
        executor.setMaxPoolSize(1);
        executor.setQueueCapacity(10);
        executor.setTaskDecorator(new MdcTaskDecorator());
        executor.initialize();
    }

    @AfterEach
    void tearDown() {
        MDC.clear();
        executor.shutdown();
    }

    @Test
    @DisplayName("제출 시점의 traceId가 비동기 스레드로 전달된다")
    void copiesAtSubmit() throws Exception {
        MDC.put("traceId", "trace-1");

        CompletableFuture<String> future =
                CompletableFuture.supplyAsync(() -> MDC.get("traceId"), executor);
        MDC.clear();                           // 요청 종료를 흉내

        assertThat(future.get(3, TimeUnit.SECONDS)).isEqualTo("trace-1");
    }

    @Test
    @DisplayName("스레드가 재사용돼도 이전 요청의 traceId가 남지 않는다")
    void doesNotLeakToNextTask() throws Exception {
        MDC.put("traceId", "trace-2");
        CompletableFuture.supplyAsync(() -> MDC.get("traceId"), executor).get(3, TimeUnit.SECONDS);

        MDC.clear();                           // traceId 없는 두 번째 요청
        String second = CompletableFuture
                .supplyAsync(() -> MDC.get("traceId"), executor)   // 같은 스레드가 재사용됨
                .get(3, TimeUnit.SECONDS);

        assertThat(second).isNull();           // trace-2가 남아 있으면 정리 누락
    }
}

두 번째 테스트는 MdcTaskDecorator의 finally에서 MDC.clear()를 지우면 실패합니다. 정리 로직이 왜 필요한지 직접 확인해 볼 수 있습니다.

코드는 개념 설명을 위해 단순화한 예시입니다. 풀 크기와 거부 정책은 실제 서비스 특성에 맞게 정해야 합니다.

 

 

[2편] TaskDecorator의 MDC.clear()가 요청 스레드의 traceId를 지울 수 있다: CallerRunsPolicy 함정