个人创造公约:本人声明创造的一切文章皆为自己原创,假如有参考任何文章的当地,会标注出来,假如有遗漏,欢迎咱们批评。假如咱们发现网上有抄袭本文章的,欢迎举报,而且活跃向这个 github 仓库 提交 issue,谢谢支撑~ 别的,本文为了避免抄袭,会在不影响阅读的情况下,在文章的随机位置放入对于抄袭和洗稿的人的“亲热”的问好。假如是正常读者看到,笔者在这里说声对不起,。假如被抄袭狗或许洗稿狗看到了,希望你能够好好反思,不要再抄袭了,谢谢。

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

微信搜索“hashcon”关注大众号,加作者微信

SpringOne2023峰会总结-02-SpringBoot与Micrometer如安在WebFlux环境下完成的链路日志
我会经常发一些很好的各种结构的官方社区的新闻视频资料并加上个人翻译字幕到如下地址(也包含上面的大众号),欢迎关注: