[개요]

본 프로젝트는 Spring Boot와 MySQL을 활용한 모의 면접 서비스입니다.

이 글은 사용자 요청에 대한 로그를 추적하는 과정에서 스레드 풀 재사용으로 인한 로그 추적 문제를 MDC를 통해 해결한 내용에 대해 설명합니다. ThreadLocal 이라는 MDC 특성상 비동기 스레드를 사용했을 때 MDC가 전파되지 않는 문제와 멀티 서비스 환경에서 다른 서버로 요청을 보낼 때 MDC 값이 사라지는 문제에 대한 해결에 대해서도 다룹니다.

[요약]

톰캣 스레드 풀 재사용과 서버 다중화 환경에서 요청별 로그 추적이 가능하도록 MDC를 적용했습니다.

TaskDecorator를 통해 MDC 컨텍스트를 비동기 스레드로 전파하고, Nginx에서 전달받은 고유한 X-Request-ID 헤더를 다른 서버 요청 시에도 함께 전달하여 멀티 서비스 환경에서도 MDC 기반 로그 추적을 가능하게 했습니다.

[문제 상황 1 : 스레드 이름 중복으로 인한 로그 추적 문제]

톰캣은 스레드 풀을 재사용하기 때문에 스레드 이름만으로 로그를 추적하면 서로 다른 요청의 로그가 뒤섞이게 됩니다.

타임스탬프를 통해 어느 정도 구분할 수 있지만, 동시에 처리되는 여러 요청에서는 완벽한 구분이 불가능합니다. 특히 프로덕션 환경에서는 서버가 다중화되어 있어 스레드 이름과 타임스탬프만으로는 요청별 구분이 더욱 어려워집니다.

위 그림에서 볼 수 있듯이 서로 다른 요청임에도 불구하고 동일한 스레드 이름을 사용하는 것을 확인할 수 있습니다.

이렇게 로그가 뒤섞이면 장애 발생 시 원인을 추적하고 문제를 진단하는 데 상당한 어려움이 발생합니다.

✅ [해결 방안 1 : MDC 적용]

http {
    # ...
    server {
        listen 80;
        # ...
        
        location / {
            proxy_set_header X-Request-ID $request_id;
            # ...
        }
    }
}

@Slf4j
@Component
public class LoggingFilter extends OncePerRequestFilter {

    private static final List<String> WHITE_LIST = ...;

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        String requestId = request.getHeader("X-Request-ID");
        if (requestId != null) {
            MDC.put("requestId", requestId);
        }

        try {
            filterChain.doFilter(request, response);
        } finally {
            log.info("...");
            MDC.clear();
        }
    }

    @Override
    protected boolean shouldNotFilter(HttpServletRequest request) throws ServletException {
        // ...
    }
}

<pattern>
[%X{requestId:-noRequest}] %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n
</pattern>

먼저 nginx.conf를 위와 같이 설정하면 각 요청마다 고유한 ID 값을 X-Request-ID 헤더에 담아 서버로 전달합니다.

이후 LoggingFilter에서 MDC에 requestId를 설정하고, logback 패턴에 %X{requestId:-noRequest}를 추가하면 각 요청마다 고유한 requestId가 함께 로깅됩니다.

finally 블록에서 MDC.clear()를 호출하는 이유는 톰캣 스레드 풀 재사용으로 인한 MDC 오염을 방지하기 위함입니다. MDC는 ThreadLocal을 사용하므로 스레드가 재사용될 때 이전 요청의 MDC 값이 남아있을 수 있습니다. 예외 발생 여부와 관계없이 반드시 정리해야 하므로 finally 블록에서 처리합니다.

MDC를 통해 다중 서버 환경에서도 요청별로 로그를 명확하게 구분할 수 있어 추적성이 크게 향상됩니다.

위와같이 하나의 요청에서 발생하는 모든 로그를 MDC에 저장된 고유 값으로 쉽게 추적할 수 있게 됩니다.

[문제 상황 2 : 비동기 스레드에서 MDC 값 누락]

@Async를 사용하여 비동기 스레드에서 로그를 남기는 경우, 앞서 설정한 고유 requestId 대신 "noRequest"가 로깅되는 문제가 발생합니다.

이는 MDC가 ThreadLocal을 사용하여 컨텍스트를 관리하기 때문입니다.

톰캣 스레드에서 설정한 MDC 컨텍스트는 해당 스레드에서만 유효하므로, 새로운 비동기 스레드가 생성되면 이 스레드는 기존 MDC 컨텍스트에 접근할 수 없습니다. 따라서 비동기 스레드에서는 MDC 값이 누락되어 추적이 불가능해집니다.

✅ [해결 방안 2 : TaskDecorator 적용]

비동기 스레드에도 MDC 컨텍스트를 전달해야 합니다.

비동기 스레드 호출 시마다 파라미터로 MDC를 전달할 수도 있지만, 코드 중복과 누락 가능성을 고려하여 TaskDecorator를 통해 자동으로 MDC 값을 전파하도록 구현했습니다.

// AsyncConfig.java
public ThreadPoolTaskExecutor taskExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setTaskDecorator(mdcDecorator);
    // ...
    return executor;
}

// MdcDecorator.java
@Component
public class MdcDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> contextMap = MDC.getCopyOfContextMap();

        return () -> {
            if (contextMap != null) {
                MDC.setContextMap(contextMap);
            }
            try {
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

TaskDecorator는 비동기 작업 실행 전에 현재 스레드의 MDC 컨텍스트를 복사하고, 비동기 스레드에서 이를 설정한 후 작업을 실행합니다. 작업 완료 후에는 finally 블록에서 MDC를 정리하여 스레드 풀 재사용 시 오염을 방지합니다.

위와 같이 설정하면 비동기 스레드에서도 동일한 requestId 값이 로깅되어 전체 요청 흐름을 추적할 수 있습니다.

실제로 부하 테스트를 할때 위의 로깅을 통해 성능을 분석하였는데, 이 때 MDC가 추적에 많은 도움이 되었습니다.

[문제 상황 3 : 멀티 서비스 환경에서 MDC 값 누락]

인터뷰에 좋아요나 조회수가 특정 값에 달성하면 사용자에게 알림을 주는 기능이 있습니다.

알림 서버는 인터뷰 기능과 분리되어 독립적인 서버로 운영되고 있었습니다.

이때 인터뷰 서버에서 알림 서버로 요청을 보낼 때 별도 조치 없이는 MDC 값이 누락되는 문제가 발생합니다.

알림 서버는 인터뷰 서버의 MDC 컨텍스트를 알 수 없으므로, 서버 간 요청에서는 requestId 추적이 끊어지게 됩니다. 이로 인해 하나의 사용자 요청이 여러 서버에 걸쳐 처리될 때 전체 흐름을 추적하기 어려워집니다.

✅ [해결 방안 3 : ClientHttpRequestInterceptor로 X-Request-ID 헤더 설정]

RestClient를 통해 알림 서버로 요청 시 ClientHttpRequestInterceptor를 활용하여 현재 스레드의 requestId 값을 X-Request-ID 헤더에 자동으로 설정하도록 구현했습니다.

@Component
public class MdcInterceptor implements ClientHttpRequestInterceptor {
    
    @Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException {
        String requestId = MDC.get("requestId");
        if (requestId != null) {
            request.getHeaders().add("X-Request-ID", requestId);
        }
        return execution.execute(request, body);
    }
}

// ...

RestClient.Builder notificationClientBuilder = 
        builder.requestInterceptor(mdcInterceptor)
                ...;

MdcInterceptor는 모든 외부 서버 요청에서 현재 MDC의 requestId를 자동으로 헤더에 추가합니다. 알림 서버는 이 헤더를 받아 자신의 MDC에 설정하므로, 서버 간 경계를 넘나드는 요청에서도 동일한 requestId로 로그를 추적할 수 있습니다.

이를 통해 여러 서버에 걸쳐 분산된 로그를 하나의 requestId 값으로 통합 추적할 수 있어, 복잡한 멀티 서비스 환경에서도 완전한 요청 흐름 파악이 가능해집니다.