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

最新推荐文章于 2024-05-20 10:58:05 发布

wxystyle

最新推荐文章于 2024-05-20 10:58:05 发布

阅读量159

点赞数

文章标签： java 开发语言后端

原文链接：http://www.imooc.com/article/322514

版权

欢迎访问我的GitHub

GitHub - zq2599/blog_demos: CSDN博客专家程序员欣宸的github，这里有五百多篇原创文章的详细分类和汇总，以及对应的源码，内容涉及Java、Docker、Kubernetes、DevOPS等方面

内容：所有原创文章分类汇总及配套源码，涉及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}]：

<span style="color:#1c1f21"><span style="background-color:#f8fafc"><code class="language-xml"><span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>appender</span> <span style="color:#000000">name</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>console<span style="color:#000000">"</span></span> <span style="color:#000000">class</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>ch.qos.logback.core.ConsoleAppender<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>filter</span> <span style="color:#000000">class</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>ch.qos.logback.classic.filter.ThresholdFilter<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>level</span><span style="color:#000000">></span></span>INFO<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>level</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>filter</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>encoder</span><span style="color:#000000">></span></span>
            <span style="color:#708090"><!--%logger{10}表示类名过长时会自动缩写--></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>pattern</span><span style="color:#000000">></span></span>%d{HH:mm:ss} [%thread] %-5level %logger{10} [user-id=%X{user-id}] %msg%n<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>pattern</span><span style="color:#000000">></span></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>charset</span><span style="color:#000000">></span></span>utf-8<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>charset</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>encoder</span><span style="color:#000000">></span></span>
    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>appender</span><span style="color:#000000">></span></span>
</code></span></span>

再来看一段日志的代码，先调用MDC.put方法将一个键值对写入当前线程的诊断上下文map(diagnostic context map)，键名和上面的模板中配置的%X{user-id}一模一样：

<span style="color:#1c1f21"><span style="background-color:#f8fafc"><code class="language-java"><span style="color:#000000">@GetMapping</span><span style="color:#000000">(</span><span style="color:#000000">"/test"</span><span style="color:#000000">)</span>
    <span style="color:#000000">public</span> <span style="color:#000000">void</span> <span style="color:#f92672">test</span><span style="color:#000000">(</span><span style="color:#000000">)</span> <span style="color:#000000">{</span>
        MDC<span style="color:#000000">.</span><span style="color:#f92672">put</span><span style="color:#000000">(</span><span style="color:#000000">"user-id"</span><span style="color:#000000">,</span> <span style="color:#000000">"user-"</span> <span style="color:#000000">+</span> System<span style="color:#000000">.</span><span style="color:#f92672">currentTimeMillis</span><span style="color:#000000">(</span><span style="color:#000000">)</span><span style="color:#000000">)</span><span style="color:#000000">;</span>
        log<span style="color:#000000">.</span><span style="color:#f92672">info</span><span style="color:#000000">(</span><span style="color:#000000">"this is test request"</span><span style="color:#000000">)</span><span style="color:#000000">;</span>
    <span style="color:#000000">}</span>
</code></span></span>

现在把代码运行起来，打印日志看看，如下所示，之前模板中配置的%X{user-id}已被替换成了user-1632122267618，就是代码中MDC.put设置的值：

<span style="color:#1c1f21"><span style="background-color:#f8fafc"><code class="language-shell">15:17:47 [http-nio-18081-exec-6] INFO  c.b.j.c.c.HelloConsumerController [user-id=user-1632122267618] this is test request
</code></span></span>

以上就是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变量：

<span style="color:#1c1f21"><span style="background-color:#f8fafc"><code class="language-xml"><span style="color:#708090"><?xml version="1.0" encoding="UTF-8"?></span>

<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>configuration</span> <span style="color:#000000">scan</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>true<span style="color:#000000">"</span></span> <span style="color:#000000">scanPeriod</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>60 seconds<span style="color:#000000">"</span></span> <span style="color:#000000">debug</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>false<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>

    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>contextName</span><span style="color:#000000">></span></span>logback<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>contextName</span><span style="color:#000000">></span></span>

    <span style="color:#708090"><!--输出到控制台--></span>
    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>appender</span> <span style="color:#000000">name</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>console<span style="color:#000000">"</span></span> <span style="color:#000000">class</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>ch.qos.logback.core.ConsoleAppender<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>filter</span> <span style="color:#000000">class</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>ch.qos.logback.classic.filter.ThresholdFilter<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>level</span><span style="color:#000000">></span></span>INFO<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>level</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>filter</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>encoder</span><span style="color:#000000">></span></span>
            <span style="color:#708090"><!--%logger{10}表示类名过长时会自动缩写--></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>pattern</span><span style="color:#000000">></span></span>%d{HH:mm:ss} [%thread] %-5level %logger{10} [traceId=%X{traceId} spanId=%X{spanId} sampled=%X{sampled}] %msg%n<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>pattern</span><span style="color:#000000">></span></span>
            <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>charset</span><span style="color:#000000">></span></span>utf-8<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>charset</span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>encoder</span><span style="color:#000000">></span></span>
    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>appender</span><span style="color:#000000">></span></span>

    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>root</span> <span style="color:#000000">level</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>info<span style="color:#000000">"</span></span><span style="color:#000000">></span></span>
        <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"><</span>appender-ref</span> <span style="color:#000000">ref</span><span style="color:#000000"><span style="color:#000000">=</span><span style="color:#000000">"</span>console<span style="color:#000000">"</span></span> <span style="color:#000000">/></span></span>
    <span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>root</span><span style="color:#000000">></span></span>
<span style="color:#000000"><span style="color:#000000"><span style="color:#000000"></</span>configuration</span><span style="color:#000000">></span></span>
</code></span></span>

再去检查配置类，确认JaegerTracer实例化时用了MDCScopeManager参数，如下所示，咱们在上一章已经这么做了，可以维持不变：

<span style="color:#1c1f21"><span style="background-color:#f8fafc"><code class="language-java"><span style="color:#000000">package</span> com<span style="color:#000000">.</span>bolingcavalry<span style="color:#000000">.</span>jaeger<span style="color:#000000">.</span>provider<span style="color:#000000">.</span>config<span style="color:#000000">;</span>

<span style="color:#000000">import</span> io<span style="color:#000000">.</span>jaegertracing<span style="color:#000000">.</span>internal<span style="color:#000000">.</span>MDCScopeManager<span style="color:#000000">;</span>
<span style="color:#000000">import</span> io<span style="color:#000000">.</span>opentracing<span style="color:#000000">.</span>contrib<span style="color:#000000">.</span>java<span style="color:#000000">.</span>spring<span style="color:#000000">.</span>jaeger<span style="color:#000000">.</span>starter<span style="color:#000000">.</span>TracerBuilderCustomizer<span style="color:#000000">;</span>
<span style="color:#000000">import</span> org<span style="color:#000000">.</span>springframework<span style="color:#000000">.</span>context<span style="color:#000000">.</span>annotation<span style="color:#000000">.</span>Bean<span style="color:#000000">;</span>
<span style="color:#000000">import</span> org<span style="color:#000000">.</span>springframework<span style="color:#000000">.</span>context<span style="color:#000000">.</span>annotation<span style="color:#000000">.</span>Configuration<span style="color:#000000">;</span>

<span style="color:#000000">@Configuration</span>
<span style="color:#000000">public</span> <span style="color:#000000">class</span> JaegerConfig <span style="color:#000000">{</span>
    <span style="color:#000000">@Bean</span>
    <span style="color:#000000">public</span> TracerBuilderCustomizer <span style="color:#f92672">mdcBuilderCustomizer</span><span style="color:#000000">(</span><span style="color:#000000">)</span> <span style="color:#000000">{</span>
        <span style="color:#708090">// 1.8新特性，函数式接口</span>
        <span style="color:#000000">return</span> builder <span style="color:#000000">-</span><span style="color:#000000">></span> builder<span style="color:#000000">.</span><span style="color:#f92672">withScopeManager</span><span style="color:#000000">(</span><span style="color:#000000">new</span> MDCScopeManager<span style="color:#000000">.</span>Builder<span style="color:#000000">(</span><span style="color:#000000">)</span><span style="color:#000000">.</span><span style="color:#f92672">build</span><span style="color:#000000">(</span><span style="color:#000000">)</span><span style="color:#000000">)</span><span style="color:#000000">;</span>
    <span style="color:#000000">}</span>
<span style="color:#000000">}</span>
</code></span></span>

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

在这里插入图片描述

接下来继续修改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来汇总所有分布式服务的日志，那就更高效了

我是欣宸，期待与您一同畅游Java世界...

wxystyle

关注

0
点赞
踩
0

收藏

觉得还不错? 一键收藏
0
评论
Java应用日志如何与Jaeger的trace关联

欢迎访问我的GitHubGitHub - zq2599/blog_demos: CSDN博客专家程序员欣宸的github，这里有五百多篇原创文章的详细分类和汇总，以及对应的源码，内容涉及Java、Docker、Kubernetes、DevOPS等方面内容：所有原创文章分类汇总及配套源码，涉及Java、Docker、Kubernetes、DevOPS等；本篇概览经过[《Jaeger开发入门(java版)》]的实战，相信您已经能将自己的应用接入Jaeger，并用来跟踪定位问.
复制链接

扫一扫