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

歡迎訪問我的GitHub

https://github.com/zq2599/blog_demos

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

本篇概覽

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

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

1. 一次web請求可能有多條業務日志(log4j或者logback配置的那種)，這和您寫代碼執行log.info的次數有關，假設有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的配置文件如下，可見模板中新增了一段內容[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，咱們隨機選擇一個，鼠標點擊下圖紅框中的圓點：

• 此時會跳轉到該trace的詳情頁，注意頁面的url，如下圖紅框，里面的2037fe105d73f4a5就是traceid：

• 用2037fe105d73f4a5搜索jaeger-service-provider的日志，由於應用部署在docker中，咱們要用docker log和grep命令組合來過濾，如下所示，咱們代碼寫的日志都打印出來了，並且紅框中就是traceid等關鍵信息

• 再去查看jaeger-service-consumer的日志，如下圖紅框，本次請求相關的日志也可以通過traceid搜索到：

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

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

1. Java系列
2. Spring系列
3. Docker系列
4. kubernetes系列
5. 數據庫+中間件系列
6. DevOps系列

歡迎關注公眾號：程序員欣宸

微信搜索「程序員欣宸」，我是欣宸，期待與您一同暢游Java世界...
https://github.com/zq2599/blog_demos