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

歡迎訪問我的GitHub

https://github.com/zq2599/blog_demos

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

本篇概覽

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

• 在正式開始前，咱們先來看一個具體的問題：

1. 一次web請求可能有多條業務日誌(log4j或者logback配置的那種)，這和您寫程式碼執行<font color="blue">log.info</font>的次數有關，假設有10條，那麼十次請求就有一百條業務日誌；
2. 通過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的配置檔案如下，可見模板中新增了一段內容<font color="blue">[user-id=%X{user-id}]</font>：

<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>

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

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

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

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

• 以上就是MDC的基本功能：對日誌模板中的變數進行填充，填充的內容可以用<font color="blue">MDC.put</font>方法隨意設定；

• 此刻聰明的您應該能猜到jaeger官方的方案是如何實現的了，沒錯，就是藉助MDC將trace資訊填充到日誌模板中，這樣每行日誌都有了trace資訊，咱們在jaeger web頁面中感興趣的任何一次trace，都能找到對應的日誌了

關於Jaeger的官方方案

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

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

編碼實戰

• jaeger與MDC的關聯只是個小功能，沒必要大張旗鼓的新建專案，基於《Jaeger開發入門(java版)》的程式碼繼續開發即可，也就是說修改兩個子工程<font color="blue">jaeger-service-consumer</font>和<font color="blue">jaeger-service-provider</font>的原始碼，讓它們的業務日誌打印出Jaeger的trace資訊

• 首先從<font color="blue">jaeger-service-provider</font>工程開始，增加一個標準的logback日誌配置檔案<font color="red">logback.xml</font>，如下所示，日誌模板中已添加了<font color="blue">traceId</font>、<font color="blue">spanId</font>、<font color="blue">sampled</font>變數：

<?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());
    }
}

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

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

• 開發完成，開始驗證吧

驗證

• 像《Jaeger開發入門(java版)》那樣操作，將<font color="blue">jaeger-service-consumer</font>和<font color="blue">jaeger-service-provider</font>編譯構建制作成docker映象

• 用docker-compose將所有服務啟動，然後通過瀏覽器訪問<font color="blue">jaeger-service-consumer</font>的服務，多訪問幾次

• 開啟jaeger的web頁面，可以看到多次請求的trace，咱們隨機選擇一個，滑鼠點選下圖紅框中的圓點：

• 此時會跳轉到該trace的詳情頁，注意頁面的url，如下圖紅框，裡面的<font color="red">2037fe105d73f4a5</font>就是traceid：

• 用<font color="red">2037fe105d73f4a5</font>搜尋<font color="blue">jaeger-service-provider</font>的日誌，由於應用部署在docker中，咱們要用docker log和grep命令組合來過濾，如下所示，咱們程式碼寫的日誌都打印出來了，並且紅框中就是traceid等關鍵資訊

• 再去檢視<font color="blue">jaeger-service-consumer</font>的日誌，如下圖紅框，本次請求相關的日誌也可以通過traceid搜尋到：

• 至此，本篇實戰就完成了，Jaeger的web頁面上的任何一個trace，現在都能輕易找到與之對應的所有業務日誌，這在定位問題時簡直是如虎添翼的效果，如果您的系統用了ELK或者EFK來彙總所有分散式服務的日誌，那就更高效了

你不孤單，欣宸原創一路相伴

1. Java系列
2. Spring系列
3. Docker系列
4. kubernetes系列
5. 資料庫+中介軟體系列
6. DevOps系列

歡迎關注公眾號：程式設計師欣宸

微信搜尋「程式設計師欣宸」，我是欣宸，期待與您一同暢遊Java世界... https://github.com/zq2599/blog_demos