（WebFlux）002、如何列印紀錄檔與鏈路ID

一、背景

最近在持續改造專案，想通過紀錄檔檢視使用者所有的介面鏈路紀錄檔。在原來基於SpirngMVC的時候，那是比較好處理的，通過ThreadLocal，放入TraceId，就可以把一個TraceId傳到各個地方，然後再需要的地方取出來，相當簡單。但是在換了WebFlux，老實說，真還是有些麻煩。但這並不能難倒我們，發車！

現在把使用過程中問題和解決方式列出來，供大家參考。參考原文連結

SpringBoot 版本號： 2.6.10

二、 正文

2.1 實現方案

要實現使用者呼叫鏈路所有的紀錄檔，那麼我們就得通過唯一的ID去追蹤。大致可以通過在請求的header中攜帶token，或者通過cookie這樣的方式。考慮到大多數的使用場景，我們就使用在header中攜帶token的方式來實現。

2.2 實現方式

既然我們採取的是在header在新增token的方式，那麼如何取出來，然後又在列印紀錄檔中獲取到，這才是關鍵點。我們在SpringMVC中通常採用AOP的方式列印紀錄檔，那我們在WebFlux中是否也可以這樣做呢？

2.2.1 步驟1 - 過濾器

當然可以了。要實現攔截，當然還是先實現WebFilter，程式碼如下。

/**
 * <p>記錄traceId</p>
 *
 * @author [email protected]
 * @since 2022/8/8
 */
@Slf4j
@Configuration
public class TraceIdWebFilter implements WebFilter {

    private static final String TRACE_ID = ConstantsFields.TRACE_ID;

    @Override
    public Mono<Void> filter(ServerWebExchange exchange, WebFilterChain chain) {

        return chain.filter(exchange)
                // 放入當前上下文，類似於ThreadLocal
                .contextWrite(context -> {
                    // header 中是否有TRACE-ID
                    String traceId = exchange.getRequest().getHeaders().getFirst(TRACE_ID);

                    traceId = Optional.ofNullable(traceId).orElse("");
                    if (!StringUtils.hasText(traceId)) {
                        log.warn("TRACE_ID not present in header: {}", exchange.getRequest().getURI());
                    }
                  
                    Context contextTmp = context.put(TRACE_ID, traceId);
                    exchange.getAttributes().put(TRACE_ID, traceId);

                    return contextTmp;
                });
    }
}

實現WebFilter，通過contextWrite方法，把Header中的trace-id存入到上下文中。這個ContextWrite很重要，它是類似於ThreadLocal的東西，如果有老鐵不知道，可以參考Context翻譯文章，這裡我們就不在一一贅述啦。

實現了WebFilter後，並且放入了Context中，這樣我們是不是想ThreadLocal一樣，取出來直接用就可以了？of course！

2.2.2 步驟2 - 切面

直接貼程式碼，如下（方式一）。

/**
 * <br>紀錄檔切面</br>
 *
 * @author [email protected]
 * @since 2022/8/10
 */

@Aspect
@Configuration
@Slf4j
public class LoggerAspect {

    @Around("@annotation(com.fattycal.demo.webflux.annotation.Loggable)")
    public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {

        long start = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        if (result instanceof Mono) {
            Mono monoResult = (Mono) result;
            AtomicReference<String> traceId = new AtomicReference<>("");
            return monoResult.flatMap(ret -> Mono.subscriberContext().map(ctx -> {
                        // 從Context中取出traceId, 放入到了AtomicReference，正常變數沒辦法操作（內部類）。
                        traceId.set(ctx.getOrDefault(ConstantsFields.TRACE_ID, ""));
                        return ret;
                    }))
                    .doOnSuccess(o -> {
                        String response = "";
                        if (Objects.nonNull(o)) {
                            response = o.toString();
                        }
                        log.info("【{}】,Enter: {}.{}() with argument[s] = {}", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs());
                        log.info("【{}】,Exit: {}.{}() had arguments = {}, with result = {}, Execution time = {} ms", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs()[0],
                                response, (System.currentTimeMillis() - start));
                    });
        }

        return result;
    }
}

我們直接通過切面，來判斷響應結果是否是屬於Mono，如果是，則通過flatmap結合Mono.subscriberContext()拿到traceId，然後在doOnSuccess中列印紀錄檔。這樣的好處是，不用自己訂閱Mono.subscriberContext()。

有的哥們就會問，為啥不在doOnSuccess()中去訂閱呢？ 好問題，我們的嘗試一下。程式碼如下（方式二）。

@Aspect
@Configuration
@Slf4j
public class LoggerAspect {

    @Around("@annotation(com.fattycal.demo.webflux.annotation.Loggable)")
    public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {

        long start = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        if (result instanceof Mono) {
            Mono monoResult = (Mono) result;
            // 錯誤的實現方式
            return monoResult.doOnSuccess(obj -> Mono.subscriberContext()
                    .map(ctx -> {
                        String traceId = ctx.getOrDefault(ConstantsFields.TRACE_ID, "");
                        String response = "";
                        if (Objects.nonNull(obj)) {
                            response = obj.toString();
                        }
                        log.info("【{}】,Enter: {}.{}() with argument[s] = {}", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs());
                        log.info("【{}】,Exit: {}.{}() had arguments = {}, with result = {}, Execution time = {} ms", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs()[0],
                                response, (System.currentTimeMillis() - start));
                        return ctx;
                    })
            );

        }
        return result;
    }
}

一激動，馬上唰唰寫出來了，但是這樣寫可不可以呢（文章已標記是錯誤的寫法）？為啥說是錯誤的寫法呢，那是因為在Reactor3中，有一個至理名言，那就是nothing happens until you subscribe()。我們沒有訂閱，所以Mono.subscriberContext().map()這一個流不會被執行的（點完餐付完錢店家才確定要做）。

所以我們稍微動一下程式碼，如下。

/**
 * <br>紀錄檔切面</br>
 *
 * @author [email protected]
 * @since 2022/8/10
 */
@Aspect
@Configuration
@Slf4j
public class LoggerAspect {

    @Around("@annotation(com.fattycal.demo.webflux.annotation.Loggable)")
    public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {

        long start = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        if (result instanceof Mono) {
            Mono monoResult = (Mono) result;
            // 把doOnSuccess這個操作放到單獨執行緒池裡做
            return monoResult.publishOn(Schedulers.newElastic("fattyca1-thread-pool")).doOnSuccess(obj -> Mono.subscriberContext()
                    .map(ctx -> {
                        String traceId = ctx.getOrDefault(ConstantsFields.TRACE_ID, "");
                        String response = "";
                        if (Objects.nonNull(obj)) {
                            response = obj.toString();
                        }
                        log.info("【{}】,Enter: {}.{}() with argument[s] = {}", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs());
                        log.info("【{}】,Exit: {}.{}() had arguments = {}, with result = {}, Execution time = {} ms", traceId,
                                joinPoint.getSignature().getDeclaringTypeName(), joinPoint.getSignature().getName(),
                                joinPoint.getArgs()[0],
                                response, (System.currentTimeMillis() - start));
                        return ctx;
                    }).subscribe()
            );

        }
        return result;
    }
}

我們在map方法後面又增加了subscribe()方法，這個時候，付錢了，餐館才給你做飯。當然，我們又新增了publishOn這個方法，那是因為subscribe()是阻塞的，為了不阻塞，我們放進了一個新的執行緒池中處理。這樣我們就大功告成啦！ 馬上動手測試一下

2.2.3 品嚐果實

我們直接來一個樸實無華的測試，程式碼如下。

@RestController
public class WebfluxController {

    @RequestMapping("/hi/{name}")
    @Loggable
    public Mono<String> helloWorld(@PathVariable("name") String name) {
        return Mono.fromSupplier(() -> "hi, " + name);
    }
}

2.2.3.1 （方式一）

先按照方式一的方式來測試，結果如圖所示。

方式一測試出來，的確沒問題，我們把Header中的Trace-id列印出來了。那接下來試試方式二。

2.2.3.2 （方式二）

方式一實現方式測試，結果如圖所示。

擦，撲街了~，從測試結果看，這樣的方式是取不到Context中的值，我在嘗試去掉執行緒池後，也還是取不到Context中的值。為什麼沒有取到這一點，還沒研究透，後面研究透了給大家補上。

從結果看，我們還是通過FlatMap的方式，提前拿到Trace-id還是靠譜一點。

2.2.3.2 測試三

我們修改了一下Controller中的程式碼，通過flatMap，從Context中獲取traceId。再測試一下。結果如圖所示。

通過測試我們發下，通過flatmap，然後再從Context中獲取traceId是完全可行的，所以我們在實際使用的時候還是要注意下方式。

三、總結

先實踐，實操，在理解原理。以上為實際實踐，如果發現有問題，歡迎指出，交流！