분산 환경에서의 로깅 - 삽질중인 개발자

카테고리 없음

분산 환경에서의 로깅 - 삽질중인 개발자

개발 N년차 2025. 6. 22. 23:06

현재 운영 중인 서비스의 초기에는 하나의 서비스 내에서 모든 요청에 대한 처리를 할 수 있었지만 비즈니스가 복잡해지면서 각 서비스 간 연동이 많아졌고 그에 따라 로직 흐름을 파악하거나 장애 원인을 추적하기 위해 로깅의 중요성이 커졌다.

기존에 적용된 추적을 위한 로깅을 구현한 방식은 클라이언트로부터 요청이 Gateway에 들어오면 Gateway의 필터를 통해 x-transaction-id 헤더의 존재 여부를 확인한 후 해당 헤더가 없을 경우 새로 생성하여 요청에 추가하고 이미 존재하는 경우에는 그대로 요청을 전달한 이후 각 마이크로서비스에서는 이 헤더를 필터를 통해 MDC에 저장하여 로깅 시 트랜잭션 ID가 함께 출력되도록 구성해서 이슈에 대해서 추적을 하고 있었다.

위에서 구성한 방식으로는 단 한 번의 HTTP 요청으로 모든 로직을 처리하는 방식에서는 문제가 되는 부분이 없었지만 마이크로 서비스들이 늘어나고 이벤트 기반의 로직이 돌아가게 되면서 기존에 단순하게 HTTP 요청 하나에만 적용된 부분을 계속 사용하기에는 그 외의 상황에서는 트래킹 하는 부분이 구현이 안된 상태라서 구현이 필요한 상황이었다.

부족한 부분을 구현을 하기 위해서 찾아보던 중 Spring에서는 이미 적용된 개념과 비슷한 방식의 Micrometer tracing라는 라이브러리를 사용해서 분산 환경에서의 로깅을 지원하는 것을 발견해서 적용하기로 했다.

해당 프로젝트에서 Tracing을 하기 위해서 공식적으로 지원하는 Tracer는 OpenZipkin Brave와 OpenTelemetery를 지원한다고 해서 두 개의 Tracer를 비교한 글을 읽어보니 현재 사내 프로젝트에서 구성된 주요 서비스가 대부분 JAVA 기반인 서비스의 상황 상 및 우선 Brave가 더 적당하다고 판단해서 해당 Tracer를 적용했다.

아래는 해당 프로젝트에서 Tracing을 어떤 식으로 하는지에 대해서 그림으로 나타낸 것인데 한 개의 요청이 있을 때 Trace Id가 하나 생기고 그 요청에서 어떠한 작업이 실행될 때마다 새로운 Span Id가 생성된다. ( 참고 : 용어 사전 )

해당 프로젝트의 적용 방법은 간단했습니다.

Spring MVC 환경에서의 구성 방법

Micrometer의 Tracer 중 하나에 대해서 의존성을 추가한다.

<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>micrometer-tracing-bridge-brave</artifactId>
</dependency>

의존성을 추가 후 ObservationHandler를 해당 예제처럼 정의해 주면 되는데 기존에 spring-boot-starter-actuator를 사용하고 있으면 spring-boot-actuator-autoconfigure에 WebMvcObservationAutoConfiguration를 통해 ServerHttpObservationFilter 가 자동으로 추가되니 아래와 같은 설정만 하면 된다.

management:
  tracing:
    enabled: true

정상적으로 작동하는지 로그를 확인하기 위해서 아래와 같이 로그 설정을 해서 확인을 한다.

logging:
  pattern:
    console: "%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%X{spanId}] [%thread] %-5level %logger{36} - %msg%n"

그 후 아래와 같은 컨트롤러를 만든 후 테스트를 해보면

    @GetMapping
    public String test() {
        log.info("{}", "test");
        return "Hello World";
    }

TraceId와 SpanId가 세팅된 후 적용되는 걸 볼 수 있다.

2025-06-23 01:01:54.905 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] DEBUG o.s.web.servlet.DispatcherServlet - GET "/hello", parameters={}
2025-06-23 01:01:54.906 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped to com.example.micrometertracing.TestController#test()
2025-06-23 01:01:56.195 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] INFO  c.e.micrometertracing.TestController - test
2025-06-23 01:01:57.355 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Using 'text/html', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8, application/signed-exchange;v=b3;q=0.7] and supported [text/plain, */*, application/json, application/*+json]
2025-06-23 01:01:57.355 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Writing ["Hello World"]
2025-06-23 01:01:57.356 [685828f295b04cb1c0c0f25182dd70d2] [c0c0f25182dd70d2] [http-nio-8080-exec-4] DEBUG o.s.web.servlet.DispatcherServlet - Completed 200 OK

Reactor 기반의 서비스에서 구성 방법

사내 서비스에서는 spring-boot-web로 구성된 프로젝트도 있지만 spring-boot-web-flux로 구성된 프로젝트의 경우도 있었다. MDC는 내부적으로 ThreadLocal 기반으로 동작하기 때문에, 스레드가 변경되는 환경에서는 기본 설정만으로는 Context 정보가 전파되지 않는다.

따라서 reactor로 구성된 spring-webflux에서는 다음과 같은 Hook을 설정해야 된다. (해당 Hook 설정은 reactor 3.5 이상부터 가능하니 하위 버전은 별도로 구성해야 한다.)

Hooks.enableAutomaticContextPropagation();

2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] DEBUG o.s.w.r.r.m.a.RequestMappingHandlerMapping - [ab73ea98-2] Mapped to com.example.micrometertracing.TestController#asyncMono()
2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] INFO  c.e.micrometertracing.TestController - start
2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] DEBUG o.s.w.r.r.m.a.ResponseBodyResultHandler - [ab73ea98-2] Using 'text/html' given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8, application/signed-exchange;v=b3;q=0.7] and supported [text/plain;charset=UTF-8, text/event-stream, text/plain;charset=UTF-8, */*]
2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] DEBUG o.s.w.r.r.m.a.ResponseBodyResultHandler - [ab73ea98-2] 0..1 [java.lang.String]
2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] INFO  c.e.micrometertracing.TestController - logic
2025-06-23 21:50:06.694 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] INFO  c.e.micrometertracing.TestController - end
2025-06-23 21:50:06.695 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] DEBUG org.springframework.web.HttpLogging - [ab73ea98-2] Writing "Hello Mono"
2025-06-23 21:50:06.695 [68594d7e0bf8f4365f0727f7fbf81b8c] [5f0727f7fbf81b8c] [reactor-http-nio-2] DEBUG o.s.w.s.a.HttpWebHandlerAdapter - [ab73ea98-2] Completed 200 OK

@Async와 같은 별도 스레드에서의 구성 방법

마찬가지로 별도의 설정이 필요해서 TaskDecorator를 상속받아 구현한 후 Executor 빈을 생성할 때 setTaskDecorator로 구현된 객체를 넣어준다.

import org.slf4j.MDC;
import org.springframework.core.task.TaskDecorator;

import java.util.Map;

public class MdcTaskDecorator implements TaskDecorator {

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

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

@Bean("asyncTaskExecutor")
public Executor asyncTaskExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(2);
    executor.setMaxPoolSize(5);
    executor.setQueueCapacity(100);
    executor.setThreadNamePrefix("async-executor-");

    executor.setTaskDecorator(new MdcTaskDecorator());
    executor.initialize();
    return executor;
}

설정이 완료되면 아래와 같이 별도의 스레드에서 동작하는 경우도 context를 유지하여 traceId와 spanId가 정상적으로 찍힌다.

2025-06-23 21:37:08.563 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] DEBUG o.s.web.servlet.DispatcherServlet - GET "/hello-async", parameters={}
2025-06-23 21:37:08.569 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped to com.example.micrometertracing.TestController#async()
2025-06-23 21:37:08.577 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] INFO  c.e.micrometertracing.TestController - start
2025-06-23 21:37:08.586 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] INFO  c.e.micrometertracing.TestController - end
2025-06-23 21:37:08.586 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [async-executor-1] INFO  c.e.micrometertracing.AsyncService - asyncMethod
2025-06-23 21:37:08.592 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Using 'text/html', given [text/html, application/xhtml+xml, image/avif, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8, application/signed-exchange;v=b3;q=0.7] and supported [text/plain, */*, application/json, application/*+json]
2025-06-23 21:37:08.593 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Writing ["Hello Async"]
2025-06-23 21:37:08.598 [68594a74f174d768a626f03285db48f0] [a626f03285db48f0] [http-nio-8080-exec-1] DEBUG o.s.web.servlet.DispatcherServlet - Completed 200 OK

카프카의 구성 방법

그냥 아래와 같은 설정을 넣어주면 자동으로 설정되긴 하지만 별도의 bean을 생성해서 사용하는 경우 ObservationRegistry를 구현 후 추가하면 된다.

spring:
  kafka:
    template:
      observation-enabled: true
    listener:
      observation-enabled: true

@Component
public class MyKafkaProducer {

    private final KafkaTemplate<String, String> kafkaTemplate;
    private final ObservationRegistry observationRegistry;

    public MyKafkaProducer(KafkaTemplate<String, String> kafkaTemplate, ObservationRegistry observationRegistry) {
        this.kafkaTemplate = kafkaTemplate;
        this.observationRegistry = observationRegistry;
        this.kafkaTemplate.setObservationRegistry(observationRegistry);  // 직접 설정
    }

    public void send(String topic, String message) {
        kafkaTemplate.send(new ProducerRecord<>(topic, message));
    }
}

@Configuration
public class KafkaListenerConfig {

    @Bean
    public ConcurrentKafkaListenerContainerFactory<String, String> kafkaListenerContainerFactory(
            ConsumerFactory<String, String> consumerFactory,
            ObservationRegistry observationRegistry) {
        ConcurrentKafkaListenerContainerFactory<String, String> factory = new ConcurrentKafkaListenerContainerFactory<>();
        factory.setConsumerFactory(consumerFactory);
        factory.setObservationRegistry(observationRegistry);  // 여기서 등록
        return factory;
    }
}

Feign Client에 구성 방법

내부 서비스들과 통신을 위해 Feign을 사용하고 있는데 Feign의 값을 추적하기 위해서는 별도의 feign-micrometer라는 의존성을 추가해줘야 한다.

이렇게 해서 분산 환경에서의 로그 추적을 위한 기본 세팅이 완료된 상태이다. 여기에 ELK를 같이 사용해서 로그를 한쪽에서 보면 로그에 대한 추적이 조금 더 수월해진다.

저작자표시 (새창열림)