Java应用日志如何与Jaeger的trace关联

梦里梦外; 2022-09-12 03:50 116阅读 0赞

### 欢迎访问我的GitHub ###

> 这里分类和汇总了欣宸的全部原创(含配套源码)：[https://github.com/zq2599/blog\_demos][https_github.com_zq2599_blog_demos]

### 本篇概览 ###

*  经过[《Jaeger开发入门(java版)》][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>
                
                <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的[官方方案][Link 1]如下图所示，SDK已经把traceId、spanId、sampled写入当前线程的诊断上下文map(diagnostic context map)，只要日志模板中配置上述三个变量，就会在所有业务日志中输出它们具体的值：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16]
 *  看起来似乎非常简单，那就动手编码试试吧

### 编码实战 ###

*  jaeger与MDC的关联只是个小功能，没必要大张旗鼓的新建项目，基于[《Jaeger开发入门(java版)》][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>
                
                <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());
        }
    }

*  接下来是在业务代码中随意加几行打印日志的代码，如下图红框所示：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 1]
 *  接下来继续修改jaeger-service-consumer子工程，具体步骤与刚才改造jaeger-service-provider时一模一样，就不多占用篇幅赘述了，记得在业务代码中随意加几行日志，如下图红框：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 2]
 *  开发完成，开始验证吧

### 验证 ###

*  像[《Jaeger开发入门(java版)》][Jaeger_java]那样操作，将jaeger-service-consumer和jaeger-service-provider编译构建制作成docker镜像
 *  用docker-compose将所有服务启动，然后通过浏览器访问jaeger-service-consumer的服务，多访问几次
 *  打开jaeger的web页面，可以看到多次请求的trace，咱们随机选择一个，鼠标点击下图红框中的圆点：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 3]
 *  此时会跳转到该trace的详情页，注意页面的url，如下图红框，里面的**2037fe105d73f4a5**就是traceid：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 4]
 *  用**2037fe105d73f4a5**搜索jaeger-service-provider的日志，由于应用部署在docker中，咱们要用docker log和grep命令组合来过滤，如下所示，咱们代码写的日志都打印出来了，并且红框中就是traceid等关键信息  
    ![两行][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 5]
 *  再去查看jaeger-service-consumer的日志，如下图红框，本次请求相关的日志也可以通过traceid搜索到：  
    ![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 6]
 *  至此，本篇实战就完成了，Jaeger的web页面上的任何一个trace，现在都能轻易找到与之对应的所有业务日志，这在定位问题时简直是如虎添翼的效果，如果您的系统用了ELK或者EFK来汇总所有分布式服务的日志，那就更高效了

### 你不孤单，欣宸原创一路相伴 ###

1.  [Java系列][Java]
2.  [Spring系列][Spring]
3.  [Docker系列][Docker]
4.  [kubernetes系列][kubernetes]
5.  [数据库+中间件系列][Link 2]
6.  [DevOps系列][DevOps]

[https_github.com_zq2599_blog_demos]: https://github.com/zq2599/blog_demos
[Jaeger_java]: https://blog.csdn.net/boling_cavalry/article/details/120360141
[Link 1]: https://github.com/jaegertracing/jaeger-client-java/blob/master/jaeger-core/README.md
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/2ca713e60aaa4b6692fc5dcaf703ff21.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 1]: /images/20220828/9730dc4b50a041bc88d6ce762c5883c3.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 2]: /images/20220828/3827e51d75fa4b2f970c21175e768ddf.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 3]: /images/20220828/47e5daea30d24183a837d5b2a1dfa23e.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 4]: /images/20220828/8de5bd64cd6949bfb75e19235465a5c3.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 5]: /images/20220828/88e6d303cd9149288b96a44b121af8d9.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBA56iL5bqP5ZGY5qyj5a64_size_20_color_FFFFFF_t_70_g_se_x_16 6]: /images/20220828/4bb5ae69a3fe4da4b85eb03c96314fd6.png
[Java]: https://xinchen.blog.csdn.net/article/details/105068742
[Spring]: https://xinchen.blog.csdn.net/article/details/105086498
[Docker]: https://xinchen.blog.csdn.net/article/details/105086732
[kubernetes]: https://xinchen.blog.csdn.net/article/details/105086794
[Link 2]: https://xinchen.blog.csdn.net/article/details/105086850
[DevOps]: https://xinchen.blog.csdn.net/article/details/105086920