How is the Java application log associated with Jaeger's trace

Keywords: Java

Welcome to my GitHub

Here we classify and summarize all the original works of Xinchen (including supporting source code): https://github.com/zq2599/blog_demos

Overview of this article

  • after Introduction to Jaeger development (java version) I believe you can connect your application to Jaeger and use it to track positioning problems. This article will introduce a small and powerful auxiliary function of Jaeger, which greatly improves the convenience of positioning problems with a few changes: associate the business log with Jaeger's trace
  • Before we start, let's look at a specific question:
  1. A web request may have multiple business logs (log4j or the one configured by logback), which is related to the number of times you write code to execute log.info. If there are 10, there will be 100 business logs for 10 requests;
  2. Jaeger found that one of the ten requests took a long time. I want to find out the specific reason. Now the problem comes: there are 100 business logs. What is related to the long-time request in Jaeger?
  • You might say that some business features, such as user ID, can be written to span's tag or log. In this way, you can find the user ID through span, and then go to the log to find the log containing this user ID. this is indeed possible, but not necessarily every log has a user ID, so it is not the best way
  • Fortunately, Jaeger officially gives a simple and effective scheme: Based on MDC, Jaeger's SDK injects trace related variables into the log

About MDC

  • MDC about sl4j is not the focus of this article, so just talk about the features used in this article. If you have rich experience in 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 content [user id =% X {user ID}] is added in the template:
<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}Indicates that the class name will be automatically abbreviated when it is too long-->
            <pattern>%d{HH:mm:ss} [%thread] %-5level %logger{10} [user-id=%X{user-id}] %msg%n</pattern>
            <charset>utf-8</charset>
        </encoder>
    </appender>
  • As like as two peas, we will first read the code of a log. First we call the MDC.put method to write a key pair to the diagnostic context map(diagnostic context map) of the current thread. The key name is exactly the same as the%X{user-id} in the template above.
@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. As shown below, the% X {user ID} configured in the template has been replaced with user-1632122267618, which is the value set by MDC.put 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 contents can be set arbitrarily by MDC.put method;
  • At this moment, you should be smart enough to guess how jaeger's official scheme is implemented. Yes, it is to fill the trace information into the log template with the help of MDC, so that each line of log has trace information. We can find the corresponding log for any trace we are interested in on jaeger's web page

About Jaeger's official program

  • Jaeger's Official programme As shown in the following figure, the SDK has written traceId, spanId and sampled into the 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. Let's try coding

Coding practice

  • The association between jaeger and MDC is only a small function. There is no need to create a new project on a large scale Introduction to Jaeger development (java version) Just continue to develop the code, that is, modify the source code of the two sub projects Jaeger service consumer and Jaeger service provider, and let their business logs print Jaeger's trace information
  • Start with Jaeger service provider project and add a standard logback log configuration file logback.xml, as shown below. traceId, spanId and sampled 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>

    <!--Output to console-->
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <encoder>
            <!--%logger{10}Indicates that the class name will be automatically abbreviated when it is too long-->
            <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 and confirm that the MDCScopeManager parameter is used when JaegerTracer is instantiated, as shown below. We have done so 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 new features, functional interface
        return builder -> builder.withScopeManager(new MDCScopeManager.Builder().build());
    }
}
  • Next, add a few lines to the business code to print the log, as shown in the red box below:
  • As like as two peas of jaeger-service-provider, the next step is to continue modifying the jaeger-service-consumer sub project. The exact steps are similar to those just when we just reformed the library.
  • Development is complete, let's start verification

verification

  • image Introduction to Jaeger development (java version) Operate like that, compile and build Jaeger service consumer and Jaeger service provider into a docker image
  • Start all services with docker compose, and then access Jaeger service consumer services through the browser for several times
  • Open jaeger's web page and you can see multiple requested trace s. Let's randomly select one and click the dot in the red box below:
  • At this time, you will jump to the details page of the trace. Note the url of the page, as shown in the red box below. 2037fe105d73f4a5 is the traceid:
  • Use 2037fe105d73f4a5 to search the logs of Jaeger service provider. Since the application is deployed in docker, we need to use the combination of docker log and grep commands to filter. As shown below, the logs written by our code are printed, and the red box contains key information such as traceid
  • Then check the Jaeger service consumer log, as shown in the red box below. The logs related to this request can also be found through traceid:
  • So far, the actual combat of this article has been completed. Any trace on Jaeger's web page can now easily find all the corresponding business logs, which is a powerful effect in locating problems. If your system uses ELK or EFK to summarize the logs of all distributed services, it will be more efficient

You're not alone. Xinchen's original accompanies you all the way

  1. Java series
  2. Spring collection
  3. Docker series
  4. kubernetes series
  5. Database + middleware series
  6. DevOps series

Posted by Patrick on Mon, 20 Sep 2021 19:33:14 -0700