Java應用日誌如何與Jaeger的trace關聯

程式設計師欣宸發表於2021-12-20

Java應用日誌

歡迎訪問我的GitHub

https://github.com/zq2599/blog_demos

內容：所有原創文章分類彙總及配套原始碼，涉及Java、Docker、Kubernetes、DevOPS等；

本篇概覽

經過《Jaeger開發入門(java版)》的實戰，相信您已經能將自己的應用接入Jaeger，並用來跟蹤定位問題了，本文將介紹Jaeger一個小巧而強大的輔助功能，用少量改動大幅度提升定位問題的便利性：將業務日誌與Jaeger的trace關聯
在正式開始前，我們們先來看一個具體的問題：

一次web請求可能有多條業務日誌(log4j或者logback配置的那種)，這和您寫程式碼執行log.info的次數有關，假設有10條，那麼十次請求就有一百條業務日誌；
通過jaeger發現這十次請求中有一次耗時特別長，想定位一下具體原因，現在問題來了：一共有100條業務日誌，到底哪些是和Jaeger中耗時長的那一次請求有關？

您可能會說：有些業務特徵如user-id，我們們可以寫入span的tag或者log中，這樣通過span查到user-id，再去日誌中查詢含有此user-id的日誌即可，這樣確實可以，但未必每條日誌都有user-id，所以並非最佳方式
好在Jaeger官方給出了一種簡單有效的方案：基於MDC，Jaeger的SDK在日誌中注入trace相關的變數

關於MDC

關於sl4j的MDC不是本篇的重點，因此只把本篇用到的特性簡單說說即可，經驗豐富的您如果對MDC已經瞭解，請跳過此節
在sl4j的配置檔案中可以配置日誌的格式，例如logback的配置檔案如下，可見模板中新增了一段內容[user-id=%X{user-id}]：

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}表示類名過長時會自動縮寫-->
            <pattern>%d{HH:mm:ss} [%thread] %-5level %logger{10} [user-id=%X{user-id}] %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

再來看一段日誌的程式碼，先呼叫MDC.put方法將一個鍵值對寫入當前執行緒的診斷上下文map(diagnostic context map)，鍵名和上面的模板中配置的%X{user-id}一模一樣：

@GetMapping("/test")
    public void test() {
        MDC.put("user-id", "user-" + System.currentTimeMillis());
        log.info("this is test request");
    }

現在把程式碼執行起來，列印日誌看看，如下所示，之前模板中配置的%X{user-id}已被替換成了user-1632122267618，就是程式碼中MDC.put設定的值：

15:17:47 [http-nio-18081-exec-6] INFO  c.b.j.c.c.HelloConsumerController [user-id=user-1632122267618] this is test request

以上就是MDC的基本功能：對日誌模板中的變數進行填充，填充的內容可以用MDC.put方法隨意設定；
此刻聰明的您應該能猜到jaeger官方的方案是如何實現的了，沒錯，就是藉助MDC將trace資訊填充到日誌模板中，這樣每行日誌都有了trace資訊，我們們在jaeger web頁面中感興趣的任何一次trace，都能找到對應的日誌了

關於Jaeger的官方方案

Jaeger的官方方案如下圖所示，SDK已經把traceId、spanId、sampled寫入當前執行緒的診斷上下文map(diagnostic context map)，只要日誌模板中配置上述三個變數，就會在所有業務日誌中輸出它們具體的值：

在這裡插入圖片描述

看起來似乎非常簡單，那就動手編碼試試吧

編碼實戰

jaeger與MDC的關聯只是個小功能，沒必要大張旗鼓的新建專案，基於《Jaeger開發入門(java版)》的程式碼繼續開發即可，也就是說修改兩個子工程jaeger-service-consumer和jaeger-service-provider的原始碼，讓它們的業務日誌列印出Jaeger的trace資訊
首先從jaeger-service-provider工程開始，增加一個標準的logback日誌配置檔案logback.xml，如下所示，日誌模板中已新增了traceId、spanId、sampled變數：

<?xml version="1.0" encoding="UTF-8"?>

<configuration scan="true" scanPeriod="60 seconds" debug="false">

    <contextName>logback</contextName>

    <!--輸出到控制檯-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}表示類名過長時會自動縮寫-->
            <pattern>%d{HH:mm:ss} [%thread] %-5level %logger{10} [traceId=%X{traceId} spanId=%X{spanId} sampled=%X{sampled}] %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>

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

再去檢查配置類，確認JaegerTracer例項化時用了MDCScopeManager引數，如下所示，我們們在上一章已經這麼做了，可以維持不變：

package com.bolingcavalry.jaeger.provider.config;

import io.jaegertracing.internal.MDCScopeManager;
import io.opentracing.contrib.java.spring.jaeger.starter.TracerBuilderCustomizer;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class JaegerConfig {
    @Bean
    public TracerBuilderCustomizer mdcBuilderCustomizer() {
        // 1.8新特性，函式式介面
        return builder -> builder.withScopeManager(new MDCScopeManager.Builder().build());
    }
}

接下來是在業務程式碼中隨意加幾行列印日誌的程式碼，如下圖紅框所示：

在這裡插入圖片描述

接下來繼續修改jaeger-service-consumer子工程，具體步驟與剛才改造jaeger-service-provider時一模一樣，就不多佔用篇幅贅述了，記得在業務程式碼中隨意加幾行日誌，如下圖紅框：

在這裡插入圖片描述

開發完成，開始驗證吧

驗證

像《Jaeger開發入門(java版)》那樣操作，將jaeger-service-consumer和jaeger-service-provider編譯構建制作成docker映象
用docker-compose將所有服務啟動，然後通過瀏覽器訪問jaeger-service-consumer的服務，多訪問幾次
開啟jaeger的web頁面，可以看到多次請求的trace，我們們隨機選擇一個，滑鼠點選下圖紅框中的圓點：

在這裡插入圖片描述