关于Java应用日志与Jaeger的trace关联的问题

程序员文章站 2022-03-17 10:13:25

欢迎访问我的githubhttps://github.com/zq2599/blog_demos内容：所有原创文章分类汇总及配套源码，涉及java、docker、kubernetes、devops等；...

欢迎访问我的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)，只要日志模板中配置上述三个变量，就会在所有业务日志中输出它们具体的值：

关于Java应用日志与Jaeger的trace关联的问题

看起来似乎非常简单，那就动手编码试试吧

编码实战

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

接下来是在业务代码中随意加几行打印日志的代码，如下图红框所示：

关于Java应用日志与Jaeger的trace关联的问题

接下来继续修改jaeger-service-consumer子工程，具体步骤与刚才改造jaeger-service-provider时一模一样，就不多占用篇幅赘述了，记得在业务代码中随意加几行日志，如下图红框：

关于Java应用日志与Jaeger的trace关联的问题

开发完成，开始验证吧

验证

像[《jaeger开发入门(java版)》]那样操作，将jaeger-service-consumer和jaeger-service-provider编译构建制作成docker镜像
用docker-compose将所有服务启动，然后通过浏览器访问jaeger-service-consumer的服务，多访问几次
打开jaeger的web页面，可以看到多次请求的trace，咱们随机选择一个，鼠标点击下图红框中的圆点：

关于Java应用日志与Jaeger的trace关联的问题