How to associate Java application logs with Jaeger's trace

Welcome to my GitHub

https://github.com/zq2599/blog_demos

Content: Classification and summary of all original articles and supporting source code, involving Java, Docker, Kubernetes, DevOPS, etc.;

Overview of this article

• After "Introduction to Jaeger Development (Java Edition)" , I believe you can already connect your application to Jaeger and use it to track positioning problems. This article will introduce a small and powerful auxiliary function of Jaeger, with a few changes. Increase the convenience of locating problems: Associate business logs with Jaeger's trace
• Before the official start, let's first look at a specific problem:
• A web request may have multiple business logs (the kind configured by log4j or logback), which is related to the number of times you write code to execute <font color="blue">log.info</font>, assuming there are 10, then There are one hundred business logs for ten requests;
• Through jaeger, I found that one of these ten requests was extremely time-consuming. I wanted to locate the specific reason. Now the question is: there are 100 business logs. Which ones are related to the time-consuming request in Jaeger?
• You might say: For some business characteristics such as user-id, we can write it into the span tag or log, so that the user-id can be found through the span, and then go to the log to find the log containing this user-id. This is true Yes, but not every log has a user-id, so it is not the best way
• Fortunately, Jaeger officially gave a simple and effective solution: Based on MDC, Jaeger's SDK injects trace-related variables into the log.

About MDC

• About sl4j's MDC is not the focus of this article, so just briefly talk about the features used in this article. If you are experienced and already familiar with MDC, please skip this section
• The log format can be configured in the configuration file of sl4j. For example, the configuration file of logback is as follows. It can be seen that a new section of content is added to the template <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>

• Let’s look at a piece of log code. First call the <font color="blue">MDC.put</font> method to write a key-value pair into the current thread’s diagnostic context map (diagnostic context map), the key name and the template above The configured <font color="red"> %X{user-id} </font> are exactly the same:

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

• Now run the code and print the log to see, as shown below, the <font color="red"> %X{user-id} </font> configured in the previous template has been replaced with <font color= "blue">user-1632122267618</font> is the value set by <font color="green">MDC.put</font> in the code:

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

• The above is the basic function of MDC: fill in the variables in the log template, and the filled content can be set at will with the <font color="blue">MDC.put</font> method;
• At this moment, you should be able to guess how jaeger's official solution is implemented. Yes, it is to use MDC to fill the trace information into the log template, so that each line of the log has trace information. We can feel it in the jaeger web page. Any time you are interested in trace, you can find the corresponding log

About Jaeger's official plan

• Jaeger’s official is shown in the figure below. The SDK has already added <font color="blue">traceId</font>, <font color="blue">spanId</font>, <font color="blue"> sampled</font> is written into the diagnostic context map (diagnostic context map) of the current thread. As long as the above three variables are configured in the log template, their specific values will be output in all business logs:

• It seems very simple, then try coding

Coding combat

• The association between jaeger and MDC is just a small function, there is no need to create a new project with fanfare, based on the "Jaeger Development Introduction (java version)" code can continue to develop, that is to say, modify the two sub-projects<font color="blue" >jaeger-service-consumer</font> and <font color="blue">jaeger-service-provider</font> source code, let their business logs print out Jaeger trace information
• First, start from the <font color="blue">jaeger-service-provider</font> project and add a standard logback log configuration file <font color="red">logback.xml</font>, as shown below, The <font color="blue">traceId</font>, <font color="blue">spanId</font>, <font color="blue">sampled</font> variables have been added to the log template:

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

• Check the configuration class again and confirm that the MDCScopeManager parameter is used when JaegerTracer is instantiated. As shown below, we have done this in the previous chapter and can remain unchanged:

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

• Next is to add a few lines of code to print the log at will in the business code, as shown in the red box in the following figure:

• Next, continue to modify the <font color="blue">jaeger-service-consumer</font> sub-project. The specific steps are exactly the same as when the <font color="blue">jaeger-service-provider</font> was modified just now. I won’t take up more space to go into details, remember to add a few lines of logs to the business code at will, as shown in the red box in the following figure:

• Development is complete, let's start verification

verify

• like 161c50d8c303f9 "Introduction to Jaeger Development (Java Version)" , and set <font color="blue">jaeger-service-consumer</font> and <font color="blue">jaeger-service-provider</font >Compile and build into a docker image
• Start all services with docker-compose, and then access the service of <font color="blue">jaeger-service-consumer</font> through the browser, and visit several times
• Open jaeger's web page, you can see the traces requested multiple times, let's choose one randomly, and click the dot in the red box in the figure below:

• At this time, you will jump to the trace details page. Pay attention to the url of the page, as shown in the red box as shown in the figure below. The inside <font color="red"> 2037fe105d73f4a5 </font> is the traceid:

• Use <font color="red"> 2037fe105d73f4a5 </font> to search for the log of <font color="blue">jaeger-service-provider</font>. Since the application is deployed in docker, we need to use docker log and The grep command is combined to filter, as shown below, the logs written by our code are printed out, and the red box is the key information such as traceid

• Then check the log of <font color="blue">jaeger-service-consumer</font>, as shown in the red box as shown in the figure below. Logs related to this request can also be searched through traceid:

• At this point, the actual combat is complete. Any trace on Jaeger's web page can now easily find all the business logs corresponding to it. This is an even more powerful effect when locating problems. If your system uses ELK Or EFK to summarize the logs of all distributed services, it will be more efficient

You are not lonely, Xinchen original is with you all the way

1. Java series
2. Spring series
3. Docker series
4. kubernetes series
5. Database + Middleware Series
6. DevOps series

Welcome to pay attention to the public account: programmer Xin Chen

Search "Programmer Xin Chen" on WeChat, I am Xin Chen, and I look forward to traveling the Java world with you...
https://github.com/zq2599/blog_demos