spring cloud sleuth custom trace id

17 December 2019

Spring Cloud Sleuth를 활용하여 log correlation id를 생성하는 예제를 진행해보도록 하겠습니다.
추가로, MDC와 비교하여 reactive 환경에서 tracing id 추적이 가능한지 여부도 함께 살펴보도록 합니다.

먼저 아래와 같이 restController를 만들어 API가 호출되면 해당 값에서 path를 받아오고,
다시 httpbin.org로 쏜 다음, 해당 response에서 url을 parsing하여 response로 돌려주는 API를 만들어줍니다.
각각의 실행은 하나의 스레드에서 실행되는 것으로 보장되지 않으므로, log상에서 어떤 thread에서 실행되는지도 같이 기록하도록 설정합니다.

sleuth에서 traceId, spanId 이외에 custom한 값을 넘겨주기 위해, tracing 역시 새롭게 Bean으로 설정해줍니다.
설정을 통해, log-correlation-id 값이 넘어오게 되면 tracing을 따라 함께 field값이 전달되게 됩니다.

package org.shashaka.io;

import brave.Tracing;
import brave.propagation.B3Propagation;
import brave.propagation.ExtraFieldPropagation;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.reactive.function.client.WebClient;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
import reactor.core.publisher.Mono;

import java.net.URI;

@SpringBootApplication
@Slf4j
@RestController
public class LoggingApplication implements WebMvcConfigurer {

    public static void main(String[] args) {
        SpringApplication.run(LoggingApplication.class, args);
    }

    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new TraceInterceptor());
    }

    public static final String LOG_CORRELATION_ID = "log-correlation-id";

    @Autowired
    private WebClient webClient;

    @Bean
    public Tracing tracing() {
        return Tracing.newBuilder().propagationFactory(
                ExtraFieldPropagation.newFactory(B3Propagation.FACTORY, LOG_CORRELATION_ID)
        ).build();
    }

    @PostMapping("/test")
    public Mono<String> test(@RequestBody LogBody logBody) {

        return webClient.get()
                .uri(URI.create("https://httpbin.org/" + logBody.getPath()))
                .headers(httpHeaders -> {
                    httpHeaders.add(LOG_CORRELATION_ID, ExtraFieldPropagation.get(LOG_CORRELATION_ID));
                })
                .retrieve()
                .bodyToMono(HttpBinResponse.class)
                .retry(3)
                .flatMap(httpBinResponse -> {
                    log.info("httpBinResponse : {}", httpBinResponse);
                    return Mono.just(httpBinResponse.getUrl());
                });
    }
}
MDC와 tracing id를 비교하기 위해, request가 들어오게 되면 interceptor를 통해
각각 값을 random하게 설정해주도록 합니다.
package org.shashaka.io;

import brave.propagation.ExtraFieldPropagation;
import org.slf4j.MDC;
import org.springframework.lang.Nullable;
import org.springframework.stereotype.Component;
import org.springframework.util.StringUtils;
import org.springframework.web.servlet.HandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.UUID;

@Component
public class TraceInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
            throws Exception {

        MDC.put("logId", UUID.randomUUID().toString());

        String logId = ExtraFieldPropagation.get(LoggingApplication.LOG_CORRELATION_ID);
        if (StringUtils.isEmpty(logId)) {
            ExtraFieldPropagation.set(LoggingApplication.LOG_CORRELATION_ID, UUID.randomUUID().toString());
        }

        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler,
                                @Nullable Exception ex) throws Exception {
        MDC.remove("logId");
    }
}

log에 해당 값을 출력하기 위해 아래와 같이 converter를 설정해줍니다.
package org.shashaka.io;

import brave.propagation.ExtraFieldPropagation;
import ch.qos.logback.classic.pattern.ClassicConverter;
import ch.qos.logback.classic.spi.ILoggingEvent;

public class LogIdConverter extends ClassicConverter {
    @Override
    public String convert(ILoggingEvent event) {
        return ExtraFieldPropagation.get(LoggingApplication.LOG_CORRELATION_ID);
    }
}

아래와 같이 logback.xml을 설정해주어 application의 로그를 출력해주도록 합니다.
<configuration>
    <conversionRule conversionWord="sluethLogId" converterClass="org.shashaka.io.LogIdConverter"/>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} MDC=[%X{logId}],SLEUTH=[%sluethLogId], [%thread] %-5level %logger{36} - %msg%n
            </pattern>
        </encoder>
    </appender>

    <logger name="brave.Tracer" level="warn" />

    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

// log-correlation-id 헤더없이 호출한 경우, randomUUID가 생성되어 적용됨.

20:57:13.023 MDC=[c7725f4d-4520-4e89-b05d-045de022abf6],SLEUTH=[538dd112-cd79-458e-83ed-d26f89273e81], [http-nio-8080-exec-6] INFO  org.shashaka.io.WebClientConfig - request : [https://httpbin.org/get],[[log-correlation-id:"538dd112-cd79-458e-83ed-d26f89273e81"]]
20:57:13.382 MDC=[],SLEUTH=[538dd112-cd79-458e-83ed-d26f89273e81], [reactor-http-nio-1] INFO  org.shashaka.io.WebClientConfig - response 200
20:57:13.382 MDC=[],SLEUTH=[538dd112-cd79-458e-83ed-d26f89273e81], [reactor-http-nio-1] INFO  org.shashaka.io.FluxApplication - httpBinResponse : HttpBinResponse(url=https://httpbin.org/get)

// log-correlation-id 헤더와 함께 호출한 경우, 해당 값으로 log id가 적용됨.

20:57:42.018 MDC=[5a08973a-4b97-4e79-9d79-fe0cd79b6027],SLEUTH=[test-header], [http-nio-8080-exec-9] INFO  org.shashaka.io.WebClientConfig - request : [https://httpbin.org/get],[[log-correlation-id:"test-header"]]
20:57:42.268 MDC=[],SLEUTH=[test-header], [reactor-http-nio-1] INFO  org.shashaka.io.WebClientConfig - response 200
20:57:42.268 MDC=[],SLEUTH=[test-header], [reactor-http-nio-1] INFO  org.shashaka.io.FluxApplication - httpBinResponse : HttpBinResponse(url=https://httpbin.org/get)
MDC에서는 같은 thread인 경우는 id가 둘 다 출력되지만, 같은 request에서 다른 thread로 수행되는 경우 값이 전달되지 않는 것을 확인할 수 있습니다.
sleuth를 활용하면 extra field 전달을 통해 하나의 request에서 log id를 전달할 수 있습니다.