[26/02/22] 오늘의 개발 일지 - Logback MDC, 파일 롤링, 비동기 스레드 MDC 전파

실제 운영 중인 기술 블로그 통합 플랫폼 TechFork에 적용한 로깅 아키텍처를 정리합니다.
단순한 System.out.println 디버깅에서 벗어나, 요청 추적이 가능한 구조화된 로깅 시스템을 어떻게 구축했는지 공유합니다.

 

---

1. 왜 MDC가 필요한가?

멀티스레드 환경에서 로그를 볼 때 가장 힘든 점은 "이 로그가 어떤 요청에서 발생한 건지" 알 수 없다는 것입니다. 동시에 100명의 사용자가 검색 요청을 보내면, 로그가 뒤섞여서 특정 사용자의 요청 흐름을 추적하기가 거의 불가능합니다.

 

SLF4J의 MDC(Mapped Diagnostic Context) 는 스레드 로컬 기반의 Key-Value 저장소로, 현재 스레드에서 발생하는 모든 로그에 컨텍스트 정보를 자동으로 주입할 수 있습니다. 즉, 한 번 설정해두면 해당 요청이 끝날 때까지 모든 로그 라인에 requestId, userId 같은 정보가 자동으로 찍힙니다.

 

---

2. MDC 키 상수 정의

먼저 MDC에 넣을 키를 상수로 관리합니다. 매직 스트링을 곳곳에 흩뿌리면 오타 하나로 추적이 깨질 수 있으니, 상수 클래스로 한 곳에 모아두는 것이 좋습니다.

package com.techfork.global.constant;

public final class MdcKey {
    private MdcKey() {}

    public static final String REQUEST_ID = "requestId";
    public static final String USER_ID    = "userId";
    public static final String METHOD     = "method";
    public static final String URI        = "uri";
    public static final String CLIENT_IP  = "clientIp";
}

private 생성자로 인스턴스화를 막고, 모든 필드를 public static final로 선언합니다. 이 키들은 Logback 패턴에서 %X{requestId} 형태로 참조됩니다.

 

---

3. MdcLoggingFilter — 요청 진입점에서 MDC 세팅

HTTP 요청이 들어오는 가장 앞단에서 MDC를 세팅하는 서블릿 필터입니다.

@Slf4j
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MdcLoggingFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(
            HttpServletRequest request,
            HttpServletResponse response,
            FilterChain filterChain
    ) throws ServletException, IOException {
        long startTime = System.currentTimeMillis();
        try {
            MDC.put(MdcKey.REQUEST_ID,
                    UUID.randomUUID().toString().replace("-", "").substring(0, 12));
            MDC.put(MdcKey.METHOD, request.getMethod());
            MDC.put(MdcKey.URI, request.getRequestURI());
            MDC.put(MdcKey.CLIENT_IP, resolveClientIp(request));
            MDC.put(MdcKey.USER_ID, "anonymous");

            filterChain.doFilter(request, response);

            log.info("{} {} {} {}ms",
                    request.getMethod(),
                    request.getRequestURI(),
                    response.getStatus(),
                    System.currentTimeMillis() - startTime);
        } finally {
            MDC.clear();
        }
    }

    private String resolveClientIp(HttpServletRequest request) {
        String ip = request.getHeader("X-Forwarded-For");
        if (isValid(ip)) return ip.split(",")[0].trim();

        ip = request.getHeader("X-Real-IP");
        if (isValid(ip)) return ip;

        return request.getRemoteAddr();
    }

    private boolean isValid(String ip) {
        return ip != null && !ip.isBlank() && !"unknown".equalsIgnoreCase(ip);
    }
}

핵심 포인트

@Order(Ordered.HIGHEST_PRECEDENCE) — 이 필터가 다른 모든 필터보다 먼저 실행되어야 합니다. Spring Security의 JwtAuthenticationFilter보다 앞서야, JWT 인증 과정에서 발생하는 로그에도 requestId가 찍힙니다.

 

OncePerRequestFilter — 서블릿 포워드 등으로 같은 요청이 필터 체인을 두 번 타는 경우를 방지합니다.

requestId를 12자리로 자르는 이유 — UUID 전체(32자)는 로그 한 줄에서 너무 길어 가독성을 해칩니다. 12자리면 충돌 확률이 사실상 0에 가까우면서도 로그가 깔끔합니다.

 

finally 블록에서 MDC.clear() — 톰캣의 스레드 풀은 스레드를 재사용합니다. clear를 안 하면 이전 요청의 MDC 값이 다음 요청에 오염될 수 있습니다. 이건 정말 중요한 부분이니 절대 빠뜨리면 안 됩니다.

 

클라이언트 IP 추출 — Nginx나 Cloudflare 같은 리버스 프록시 뒤에 있으면 request.getRemoteAddr()가 프록시 IP를 반환합니다. X-Forwarded-For 헤더를 우선 확인하고, 다중 프록시 환경에서는 첫 번째 IP가 실제 클라이언트 IP입니다.

 

---

4. JWT 인증 시 userId 업데이트

MdcLoggingFilter에서는 인증 전이므로 userId를 "anonymous"로 설정합니다. 이후 JwtAuthenticationFilter에서 토큰 검증이 성공하면 실제 사용자 ID로 교체합니다.

// JwtAuthenticationFilter 내부
Long userId = jwtUtil.getUserIdFromToken(jwt);
MDC.put(MdcKey.USER_ID, String.valueOf(userId));

이렇게 하면 인증 전 로그에는 uid=anonymous, 인증 후 로그에는 uid=42처럼 실제 사용자 ID가 찍힙니다.

 

---

5. Logback 설정 — 프로파일별 전략

logback-spring.xml에서 Spring Profile에 따라 로깅 전략을 분리합니다.

 

5-1. 공통 콘솔 Appender

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>
            %d{HH:mm:ss.SSS} %highlight(%-5level) [%cyan(%thread)]
            [rid=%X{requestId:-?} uid=%X{userId:-?}]
            %boldWhite(%logger{36}) - %msg%n
        </pattern>
        <charset>UTF-8</charset>
    </encoder>
</appender>

%X{requestId:-?}에서 :-?는 MDC에 값이 없을 때 ?를 출력하라는 의미입니다. 배치 작업처럼 HTTP 요청 외부에서 실행되는 코드에서도 로그 포맷이 깨지지 않습니다.

%highlight, %cyan, %boldWhite는 콘솔에서 색상을 입혀 가독성을 높이는 Logback 변환 키워드입니다. 로컬 개발할 때 에러는 빨간색, 워닝은 노란색으로 한눈에 구분할 수 있습니다.

 

5-2. local 프로파일 — 콘솔만

<springProfile name="local,local-tunnel">
    <logger name="com.techfork" level="DEBUG"/>
    <logger name="org.hibernate.SQL" level="DEBUG"/>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>
</springProfile>

로컬 개발에서는 파일 로그가 필요 없습니다. 콘솔에 DEBUG 레벨까지 출력해서 빠른 디버깅에 집중합니다. Hibernate SQL 로그도 DEBUG로 열어서 JPA가 생성하는 실제 쿼리를 확인합니다.

 

5-3. dev 프로파일 — 콘솔 + 파일 롤링 + 에러 분리 + 크롤러 분리

개발/운영 서버에서는 로그를 파일로 남겨야 합니다. 여기서 핵심은 용도별 파일 분리와 롤링 정책입니다.

일반 애플리케이션 로그

<appender name="FILE_APP"
          class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/${APP_NAME}.log</file>
    <encoder>
        <pattern>
            %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread]
            [rid=%X{requestId:-?} uid=%X{userId:-?}
             ip=%X{clientIp:-?} %X{method:-?} %X{uri:-?}]
            %logger{36} - %msg%n
        </pattern>
    </encoder>
    <rollingPolicy
        class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>
            ${LOG_DIR}/archive/${APP_NAME}.%d{yyyy-MM-dd}.%i.log.gz
        </fileNamePattern>
        <maxFileSize>100MB</maxFileSize>
        <maxHistory>30</maxHistory>
        <totalSizeCap>3GB</totalSizeCap>
    </rollingPolicy>
</appender>

에러 전용 로그

<appender name="FILE_ERROR"
          class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/${APP_NAME}-error.log</file>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>ERROR</level>
    </filter>
    <!-- 동일한 패턴, 단 maxHistory는 60일로 더 길게 -->
    <rollingPolicy
        class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>
            ${LOG_DIR}/archive/${APP_NAME}-error.%d{yyyy-MM-dd}.%i.log.gz
        </fileNamePattern>
        <maxFileSize>100MB</maxFileSize>
        <maxHistory>60</maxHistory>
        <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
</appender>

RSS 크롤러 전용 로그

<appender name="FILE_CRAWLER"
          class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_DIR}/${APP_NAME}-crawler.log</file>
    <encoder>
        <pattern>
            %d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread]
            [rid=%X{requestId:-?}] %logger{36} - %msg%n
        </pattern>
    </encoder>
    <rollingPolicy
        class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>
            ${LOG_DIR}/archive/${APP_NAME}-crawler.%d{yyyy-MM-dd}.%i.log.gz
        </fileNamePattern>
        <maxFileSize>100MB</maxFileSize>
        <maxHistory>7</maxHistory>
        <totalSizeCap>1GB</totalSizeCap>
    </rollingPolicy>
</appender>

파일 분리 전략 정리

파일	용도	보관 기간	총 용량 제한
techfork.log	전체 애플리케이션 로그	30일	3GB
techfork-error.log	ERROR 레벨만 분리	60일	1GB
techfork-crawler.log	RSS 크롤링 전용	7일	1GB

에러 로그를 따로 분리하는 이유는 간단합니다. 장애 발생 시 수백 MB의 일반 로그를 grep하는 것보다, 에러만 모인 파일을 바로 열어보는 것이 훨씬 빠릅니다. 에러 보관 기간을 60일로 길게 잡은 것도 같은 이유입니다. 지난 달에 발생한 간헐적 에러의 패턴을 분석해야 할 때가 있기 때문입니다.

 

크롤러 로그를 분리하는 이유도 마찬가지입니다. TechFork는 매 시간마다 30개 이상의 기술 블로그를 크롤링하는데, 이 과정에서 발생하는 로그가 API 요청 로그와 섞이면 분석이 어렵습니다. additivity="false"로 root 로거에 중복 기록되지 않게 막는 것도 중요합니다.

<logger name="com.techfork.domain.source"
        level="DEBUG" additivity="false">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="ASYNC_FILE_CRAWLER"/>
    <appender-ref ref="ASYNC_FILE_ERROR"/>
</logger>

 

SizeAndTimeBasedRollingPolicy 롤링 정책

SizeAndTimeBasedRollingPolicy는 시간과 파일 크기 두 가지 조건으로 롤링합니다.

• maxFileSize: 100MB — 단일 파일이 100MB를 넘으면 %i 인덱스를 증가시켜 새 파일 생성
• maxHistory: 30 — 30일이 지난 아카이브 파일 자동 삭제
• totalSizeCap: 3GB — maxHistory 내라도 전체 크기가 3GB를 넘으면 오래된 것부터 삭제
• .log.gz — 아카이브 파일을 gzip 압축하여 디스크 절약

이 세 가지 제한을 조합하면 로그가 디스크를 잡아먹는 사고를 방지할 수 있습니다. 실제로 예산이 제한된 프로젝트에서 디스크 용량 관리는 매우 중요합니다.

 

---

6. AsyncAppender — 로깅이 비즈니스 로직을 블로킹하지 않게

파일 I/O는 느립니다. 모든 로그를 동기로 파일에 쓰면 API 응답 시간이 늘어납니다. Logback의 AsyncAppender는 로그 이벤트를 내부 큐에 넣고 별도 스레드가 비동기로 파일에 기록합니다.

<appender name="ASYNC_FILE_APP"
          class="ch.qos.logback.classic.AsyncAppender">
    <discardingThreshold>0</discardingThreshold>
    <queueSize>1024</queueSize>
    <includeCallerData>false</includeCallerData>
    <appender-ref ref="FILE_APP"/>
</appender>

 

discardingThreshold: 0 — 기본값은 큐의 80%가 차면 TRACE, DEBUG 레벨 로그를 버립니다. 0으로 설정하면 어떤 레벨도 버리지 않습니다.

queueSize: 1024 — 큐 크기입니다. 로그 발생 속도가 쓰기 속도를 초과하면 큐가 가득 차고, 그 시점부터 동기 쓰기로 전환됩니다.

includeCallerData: false — 호출 스택 정보 수집을 끕니다. 이게 true면 매 로그마다 스택트레이스를 생성하므로 성능이 크게 저하됩니다. 에러 전용 AsyncAppender에서만 true로 설정하여, 에러 발생 위치를 정확히 추적합니다.

 

---

7. 비동기 스레드에서 MDC 전파 — MdcTaskDecorator

여기가 가장 중요한 부분입니다. MDC는 ThreadLocal 기반이기 때문에, @Async나 AsyncItemProcessor 같은 비동기 처리에서 새 스레드가 생성되면 MDC 값이 사라집니다.

public class MdcTaskDecorator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        // 1. 부모 스레드의 MDC 컨텍스트를 캡처
        Map<String, String> mdcContext = MDC.getCopyOfContextMap();

        return () -> {
            try {
                // 2. 자식 스레드에 MDC 컨텍스트를 복원
                if (mdcContext != null) {
                    MDC.setContextMap(mdcContext);
                }
                runnable.run();
            } finally {
                // 3. 작업 완료 후 반드시 정리 (스레드 풀 재사용 대비)
                MDC.clear();
            }
        };
    }
}

원리는 단순합니다. 작업이 큐에 들어가는 시점(부모 스레드)에서 MDC를 복사해두고, 실제 실행 시점(자식 스레드)에서 복원합니다. 클로저를 활용한 컨텍스트 전파 패턴입니다.

 

ThreadPoolTaskExecutor에 등록

이 데코레이터를 ThreadPoolTaskExecutor에 등록하면, 해당 스레드 풀에서 실행되는 모든 비동기 작업에 MDC가 자동 전파됩니다.

@Configuration
@EnableAsync
public class AsyncConfig {

    @Bean(name = "taskExecutor")
    public Executor taskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(4);
        executor.setMaxPoolSize(8);
        executor.setQueueCapacity(50);
        executor.setThreadNamePrefix("async-");
        executor.setTaskDecorator(new MdcTaskDecorator());  // ← 여기!
        executor.setWaitForTasksToCompleteOnShutdown(true);
        executor.setAwaitTerminationSeconds(30);
        executor.initialize();
        return executor;
    }
}

setTaskDecorator(new MdcTaskDecorator()) 한 줄이면 됩니다. 이것만으로 @Async 메서드에서 찍는 로그에도 원래 요청의 requestId가 그대로 살아있습니다.

도메인별 스레드 풀에도 동일하게 적용

TechFork에서는 검색, 추천, 크롤링 각각 전용 스레드 풀을 분리해서 운영합니다. 모든 스레드 풀에 MdcTaskDecorator를 일관되게 적용합니다.

// 검색 전용 — 고성능, 큰 스레드 풀
@Bean(name = "searchAsyncExecutor")
public Executor searchAsyncExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(20);
    executor.setMaxPoolSize(50);
    executor.setQueueCapacity(100);
    executor.setTaskDecorator(new MdcTaskDecorator());
    executor.setThreadNamePrefix("SearchExec-");
    executor.setRejectedExecutionHandler(
            new ThreadPoolExecutor.CallerRunsPolicy());
    return executor;
}

// 추천 전용 — 검색에 영향을 주지 않도록 분리
@Bean(name = "recommendationAsyncExecutor")
public Executor recommendationAsyncExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(4);
    executor.setMaxPoolSize(8);
    executor.setQueueCapacity(20);
    executor.setTaskDecorator(new MdcTaskDecorator());
    executor.setThreadNamePrefix("recommendation-");
    // ...
    return executor;
}

// Spring Batch 요약 처리 전용
@Bean
public TaskExecutor summaryTaskExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(2);
    executor.setMaxPoolSize(2);
    executor.setThreadNamePrefix("summary-");
    executor.setTaskDecorator(new MdcTaskDecorator());
    // ...
    return executor;
}

// Spring Batch 임베딩 처리 전용
@Bean
public TaskExecutor embeddingTaskExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(10);
    executor.setMaxPoolSize(20);
    executor.setThreadNamePrefix("embedding-");
    executor.setTaskDecorator(new MdcTaskDecorator());
    // ...
    return executor;
}

---

8. Spring Batch에서의 MDC 활용

HTTP 요청이 아닌 배치 작업에서는 서블릿 필터가 동작하지 않습니다. 이때는 JobExecutionListener에서 직접 MDC를 세팅합니다.

@Slf4j
@Component
@RequiredArgsConstructor
public class RssCrawlingJobListener implements JobExecutionListener {

    @Override
    public void beforeJob(JobExecution jobExecution) {
        MDC.put(MdcKey.REQUEST_ID, "batch-" + jobExecution.getId());
        MDC.put(MdcKey.USER_ID, "system");
        log.info("RSS crawling job started: jobExecutionId={}, startTime={}",
                jobExecution.getId(), jobExecution.getStartTime());
    }

    @Override
    public void afterJob(JobExecution jobExecution) {
        // 성공/실패 처리 로직 ...
        MDC.clear();
    }
}

requestId를 "batch-{jobExecutionId}" 형태로 설정하면, 로그에서 HTTP 요청 로그와 배치 로그를 즉시 구분할 수 있습니다. userId는 "system"으로 두어 배치 작업임을 명확히 합니다.

배치 Step에서 AsyncItemProcessor를 사용하면 자식 스레드가 생성되는데, 앞서 summaryTaskExecutor와 embeddingTaskExecutor에 MdcTaskDecorator를 등록해두었으므로 배치의 비동기 처리에서도 MDC가 자연스럽게 전파됩니다.

---

9. 전체 아키텍처 흐름 정리

[HTTP 요청 진입]
    │
    ▼
MdcLoggingFilter (최우선 순위)
    ├── MDC.put(requestId, userId="anonymous", method, uri, clientIp)
    │
    ▼
JwtAuthenticationFilter
    ├── MDC.put(userId, 실제 사용자 ID)
    │
    ▼
Controller → Service → Repository
    │         모든 로그에 MDC 값 자동 포함
    │
    ├── @Async 비동기 호출 ──→ MdcTaskDecorator가 MDC 복사
    │                            └── 자식 스레드에서도 동일한 requestId
    │
    ▼
MdcLoggingFilter.finally
    └── MDC.clear()


[배치 작업]
    │
    ▼
RssCrawlingJobListener.beforeJob()
    ├── MDC.put(requestId="batch-{id}", userId="system")
    │
    ▼
Step 1: RSS 수집 → Step 2: 요약(Async) → Step 3: 임베딩(Async)
    │                  │                      │
    │            MdcTaskDecorator         MdcTaskDecorator
    │              MDC 전파                 MDC 전파
    │
    ▼
RssCrawlingJobListener.afterJob()
    └── MDC.clear()

 

---

10. 실제 로그 출력 예시

콘솔 (로컬 개발)

09:15:32.441 INFO  [http-nio-8080-exec-3] [rid=a1b2c3d4e5f6 uid=42] SearchService - 하이브리드 검색 시작: query=Spring Boot
09:15:32.890 INFO  [SearchExec-1]         [rid=a1b2c3d4e5f6 uid=42] ElasticSearchService - BM25 검색 완료: hits=15
09:15:33.120 INFO  [SearchExec-2]         [rid=a1b2c3d4e5f6 uid=42] EmbeddingService - 시맨틱 검색 완료: hits=20

스레드 이름은 http-nio에서 SearchExec으로 바뀌었지만, rid=a1b2c3d4e5f6으로 같은 요청임을 추적할 수 있습니다. 이게 바로 MDC 전파의 힘입니다.

 

파일 (운영 서버)

2025-02-15 05:00:01.234 INFO  [scheduling-1] [rid=batch-847 uid=system] RssCrawlingJobListener - RSS crawling job started: jobExecutionId=847
2025-02-15 05:00:05.678 INFO  [summary-1]    [rid=batch-847 uid=system] PostSummaryProcessor - GPT 요약 추출 완료: postId=1234
2025-02-15 05:00:12.345 INFO  [embedding-3]  [rid=batch-847 uid=system] PostEmbeddingProcessor - 임베딩 생성 완료: postId=1234, chunks=3

 

---

11. 정리

구성 요소	역할
MdcKey	MDC 키 상수 중앙 관리
MdcLoggingFilter	HTTP 요청 진입 시 MDC 세팅 및 정리
JwtAuthenticationFilter	인증 후 userId 업데이트
MdcTaskDecorator	비동기 스레드로 MDC 전파
RssCrawlingJobListener	배치 작업용 MDC 세팅
logback-spring.xml	프로파일별 로깅 전략, 파일 롤링, AsyncAppender

로깅은 "잘 되고 있을 때는 아무도 관심 없지만, 장애가 나면 모두가 찾는" 기능입니다. MDC 기반의 구조화된 로깅을 처음부터 잘 세팅해두면, 운영 단계에서 문제 추적 시간을 크게 줄일 수 있습니다.

 

특히 TechFork처럼 HTTP API, 비동기 검색, Spring Batch 크롤링이 공존하는 시스템에서는 모든 스레드 풀에 MdcTaskDecorator를 빠짐없이 등록하는 것이 핵심입니다. 하나라도 빠지면 그 스레드 풀에서 발생하는 로그는 추적 불가능한 미아가 됩니다.