SpringOne2023峰会总结-02-SpringBoot与Micrometer如何在WebFlux环境下实现的链路日志

干货满满张哈希

发布于 2024-05-25 09:04:34

1170

发布于 2024-05-25 09:04:34

02-SpringBoot与Micrometer如何在WebFlux环境下实现的链路日志

视频原始地址：https://www.youtube.com/watch?v=xF7aZJlfTSw&list=PLgGXSWYM2FpPrAdQor9pi__EV1O69Qbom&index=25
个人翻译地址：https://www.bilibili.com/video/BV12K421y7kF/
个人总结代码与介绍地址：https://github.com/HashZhang/SpringOne-2023/blob/main/02-SpringBoot与Micrometer如何在WebFlux环境下实现的链路日志

我们可以在日志中加入链路信息，这样我们可以找到某个请求，某个事务所有的日志，这样就可以方便的进行问题排查。并且，我们还可以通过 traceId 找到不同微服务调用链路相关的日志。在 Spring Boot 3.x 之前，我们一般用 spring-cloud-sleuth 去实现，但是在 Spring Boot 3.x 之后，已经去掉了对于 sleuth 的原生支持，全面改用了 micrometer。

首先，我们先思考下，这些链路日志是怎么实现的？我们知道，所有的日志框架，都带有 %X 这个日志格式占位符。这个占位符，就是从 MDC（Mapped Diagnostic Context）中取出对应 key 来实现的。MDC 是一个 ThreadLocal 的变量，它是一个 Map，我们可以在任何地方往里面放值，然后在任何地方取出来。这样，我们就可以在任何地方，把 traceId 放到 MDC 中，然后通过类似于下面的日志格式，就可以在日志中打印出来。

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

1. 不依赖任何框架，如何实现链路日志

如果我们不依赖任何框架，看看我们如何实现这个功能。首先在 web-mvc 环境下，我们可以通过拦截器，在请求进来的时候，把 traceId 放到 MDC 中，然后在请求结束的时候，把 traceId 从 MDC 中移除。

然后，我们添加一个普通的接口，这个接口里面，我们打印一下日志，看看 traceId 是否能够打印出来。这些都是在 web-mvc 环境下，我们可以很方便的实现。这里为了方便，我们把所有代码放在一个类里面：

import jakarta.servlet.Filter;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.annotation.Bean;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

@Slf4j
@SpringBootApplication
public class Main {
    public static void main(String[] args) {
        SpringApplication.run(Main.class);
    }


    /**
     * Returns an instance of the correlation filter.
     * This filter sets the Mapped Diagnostic Context (MDC) with the requested traceId parameter, if available, before executing the filter chain. After the filter chain is executed
     * , it removes the traceId from the MDC.
     *
     * @return the correlation filter
     */
    @Bean
    public Filter correlationFilter() {
        return (request, response, chain) -> {
            try {
                log.info("adding traceId");
                String name = request.getParameter("traceId");
                if (name != null) {
                    MDC.put("traceId", name);
                }
                log.info("traceId added");
                chain.doFilter(request, response);
            } finally {
                log.info("removing traceId");
                MDC.remove("traceId");
                log.info("traceId removed");
            }
        };
    }

    /**
     * The ExampleController class is a REST controller that handles the "/hello" endpoint.
     * It is responsible for returning a greeting message with the provided traceId parameter,
     * and it logs the message "hello endpoint called" when the endpoint is called.
     */
    @Slf4j
    @RestController
    public static class ExampleController {
        @GetMapping("/hello")
        String hello(@RequestParam String traceId) {
            log.info("hello endpoint called");
            return "Hello, " + traceId + "!";
        }
    }
}

启动后，我们调用 hello 接口，传入 traceId 参数（curl 'http://127.0.0.1:8080/hello?traceId=123456'），我们可以看到日志中打印出了 traceId。

2024-02-02 17:58:14.727 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][] - adding traceId
2024-02-02 17:58:14.728 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][123456] - traceId added
2024-02-02 17:58:14.736 [http-nio-8080-exec-1][INFO ][c.g.h.s.E.Main$ExampleController][123456] - hello endpoint called
2024-02-02 17:58:14.740 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][123456] - removing traceId
2024-02-02 17:58:14.740 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][] - traceId removed

我们可以看出，随着 traceId 放入 MDC，日志中开始有了 traceId，然后随着 traceId 从 MDC 中移除，日志中的 traceId 也消失了。这就是链路日志的原理。

2. 遇到问题，链路信息丢失

由于 MDC 是一个 ThreadLocal 的变量，所以在 WebFlux 的环境下，由于每个操作符都可能会切换线程（在发生 IO 的时候，或者使用 subscribeOn 或者 publishOn 这种操作符），这就导致了我们在 WebFlux 环境下，无法通过 MDC 来实现链路日志。我们举个例子：

@GetMapping("/hello2")
Mono<String> hello2(@RequestParam String traceId) {
    return Mono.fromSupplier(() -> {
        log.info("hello2 endpoint called");
        return "Hello, " + traceId + "!";
    }).subscribeOn(
            Schedulers.boundedElastic()
    ).map(s -> {
        log.info("map operator");
        return s + s;
    }).flatMap(s -> {
        log.info("flatMap operator");
        return Mono.just(s + s);
    });
}

这时候，我们调用 hello2 接口，传入 traceId 参数（curl 'http://127.0.0.1:8080/hello2?traceId=123456'），我们可以看到日志中并没有 traceId。

2024-02-02 18:09:08.398 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][] - adding traceId
2024-02-02 18:09:08.398 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][123456] - traceId added
2024-02-02 18:09:08.421 [boundedElastic-1][INFO ][c.g.h.s.E.Main$ExampleController][] - hello2 endpoint called
2024-02-02 18:09:08.421 [boundedElastic-1][INFO ][c.g.h.s.E.Main$ExampleController][] - map operator
2024-02-02 18:09:08.421 [boundedElastic-1][INFO ][c.g.h.s.E.Main$ExampleController][] - flatMap operator
2024-02-02 18:09:08.423 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][123456] - removing traceId
2024-02-02 18:09:08.424 [http-nio-8080-exec-1][INFO ][c.g.h.s.Example_01.Main][] - traceId removed

同时，我们可以看到，我们在 hello2 方法中，使用了 subscribeOn 操作符，这就导致了我们的代码在 boundedElastic 线程中执行，而不是在 http-nio-8080-exec-1 线程中执行。这就导致了我们在 WebFlux 环境下，无法通过 MDC 来实现链路日志。

3. 解决方案，以及观察纯 Webflux 下的效果

Micrometer 社区做了很多兼容各种框架的工作，我们首先添加依赖：

<dependency>
    <groupId>io.micrometer</groupId>
    <artifactId>context-propagation</artifactId>
    <version>1.0.4</version>
</dependency>

然后，通过以下代码启用 Project Reactor 的 ContextPropagation：

Hooks.enableAutomaticContextPropagation();

以上代码的作用是，在 WebFlux 的各种操作符的时候，会自动把当前的 Context 传递到下游中。

然后，添加 context-propagation 中从线程上下文获取信息的功能，同时，在这里将 MDC 中 traceId 信息提取：

ContextRegistry.getInstance().registerThreadLocalAccessor(
    //key
    "traceId",
    //提取什么信息，这里提取 MDC 中的 traceId
    () -> MDC.get("traceId"),
    //设置什么信息，这里设置 MDC 中的 traceId
    traceId -> MDC.put("traceId", traceId),
    //清理什么信息，这里清理 MDC 中的 traceId
    () -> MDC.remove("traceId"));

之后，重启我们的应用，我们调用 hello2 接口，传入 traceId 参数（curl 'http://http://127.0.0.1:8080/hello2?traceId=123456'）：

2024-02-02 19:49:47.729 [http-nio-8080-exec-9][INFO ][c.g.h.s.Example_01.Main][] - adding traceId
2024-02-02 19:49:47.730 [http-nio-8080-exec-9][INFO ][c.g.h.s.Example_01.Main][123456] - traceId added
2024-02-02 19:49:47.730 [boundedElastic-3][INFO ][c.g.h.s.E.Main$ExampleController][123456] - hello2 endpoint called
2024-02-02 19:49:47.731 [boundedElastic-3][INFO ][c.g.h.s.E.Main$ExampleController][123456] - map operator
2024-02-02 19:49:47.731 [http-nio-8080-exec-9][INFO ][c.g.h.s.Example_01.Main][123456] - removing traceId
2024-02-02 19:49:47.731 [boundedElastic-3][INFO ][c.g.h.s.E.Main$ExampleController][123456] - flatMap operator
2024-02-02 19:49:47.731 [http-nio-8080-exec-9][INFO ][c.g.h.s.Example_01.Main][] - traceId removed

我们可以看到，我们在 hello2 方法中，使用了 subscribeOn 操作符，这就导致了我们的代码在 boundedElastic 线程中执行，而不是在 http-nio-8080-exec-1 线程中执行。但是，我们可以看到，我们的日志中，traceId 依然被打印出来了。这就是我们通过 Micrometer 实现链路日志的原理。

4. 框架自动实现链路日志

上面我们演示的工作，其实框架都会帮我们做了。我们只需要添加依赖：

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

重新编写代码，依然需要启用 Project Reactor 的 ContextPropagation：

import jakarta.servlet.Filter;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
import reactor.core.publisher.Hooks;
import reactor.core.publisher.Mono;
import reactor.core.scheduler.Schedulers;

@Slf4j
@SpringBootApplication
public class Main {
    public static void main(String[] args) {
        Hooks.enableAutomaticContextPropagation();
        SpringApplication.run(Main.class);
    }
    
    @Slf4j
    @RestController
    public static class ExampleController {
        @GetMapping("/hello")
        String hello() {
            log.info("hello endpoint called");
            return "Hello!";
        }

        @GetMapping("/hello2")
        Mono<String> hello2() {
            return Mono.fromSupplier(() -> {
                log.info("hello2 endpoint called");
                return "Hello2!";
            }).subscribeOn(
                    Schedulers.boundedElastic()
            ).map(s -> {
                log.info("map operator");
                return s + s;
            }).flatMap(s -> {
                log.info("flatMap operator");
                return Mono.just(s + s);
            });
        }
    }
}

之后，重启我们的应用，调用 hello 和 hello2 接口，可以看到日志中都有 traceId。

2024-02-02 20:32:11.263 [http-nio-8080-exec-5][INFO ][c.g.h.s.E.Main$ExampleController][65bce0cb58b130d852320a114ffa79d0] - hello endpoint called
2024-02-02 20:32:13.262 [boundedElastic-2][INFO ][c.g.h.s.E.Main$ExampleController][65bce0cd3ca3e1a311aaa81e13317436] - hello2 endpoint called
2024-02-02 20:32:13.262 [boundedElastic-2][INFO ][c.g.h.s.E.Main$ExampleController][65bce0cd3ca3e1a311aaa81e13317436] - map operator
2024-02-02 20:32:13.262 [boundedElastic-2][INFO ][c.g.h.s.E.Main$ExampleController][65bce0cd3ca3e1a311aaa81e13317436] - flatMap operator

本文参与腾讯云自媒体同步曝光计划，分享自作者个人站点/博客。

原始发表：2024-05-24，如有侵权请联系 cloudcommunity@tencent.com 删除

框架