How did Spring Cloud Sleuth add tracing information to logback log lines?

Question

I have web application based on Spring Boot and it uses logback for logging.

I also inherit some logback defaults from spring boot using:

<include resource="org/springframework/boot/logging/logback/base.xml"/>

I want to start logging tracing information, so I added:

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

Sleuth adds tracing information to log lines, but I can't find any %X or %mdc in patterns: https://github.com/spring-projects/spring-boot/blob/2.3.x/spring-boot-project/spring-boot/src/main/resources/org/springframework/boot/logging/logback/defaults.xml

How does Sleuth add tracing information into log lines?

I use spring-cloud-starter-parent Hoxton.SR9 parent which brings Spring Boot 2.3.5.RELEASE and spring-cloud-starter-sleuth 2.2.6.RELEASE

Violoncellist

As documented? docs.spring.io/spring-cloud-sleuth/docs/current-SNAPSHOT/… – Darcydarda

I saw the documentation but it doesn't contain more details, so I'm interested in those details. – Kiyohara

I already digged into source code, I can see org.springframework.cloud.sleuth.log.Slf4jScopeDecorator adds information into MDC, but I don't understand how it is added into log line after log level. It is not mentioned in default log pattern defined in Boot. It's not only curiosity, I also have another project based on log4j2 where it doesn't work out of the box. The more ethical approach would be not to attack somebody based on unvalidated assumption. – Kiyohara

@Darcydarda it was useful for me. I was actually searching for the exact same thing and since OP asked first, it helped me. I think the amount of upvotes show OP's curiosity helped others – Emmalineemmalyn

Answer 1

(tl;dr at the bottom)
From the question I suppose you already figured out that the traceId and spanId are placed into the MDC.

If you take a look at the log integration section of the sleuth docs you will see that the tracing info in the example is between the log level (ERROR) and the pid (97192). If you try to match this with the logback config you will see that there is nothing between the log level and the pid: ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } so how the tracing information get there could be a valid question.

If you take another look to the docs, it says this:

This log configuration was automatically setup by Sleuth. You can disable it by disabling Sleuth via spring.sleuth.enabled=false property or putting your own logging.pattern.level property.

Which still not explicitly explains the mechanism but it gives you a huge hint:

putting your own logging.pattern.level property

Based on this, you could think that there is nothing between the log level and the pid, Sleuth simply overrides the log level and places the tracing information into it. And if you search for the property that the docs mention in the code, you will found out that it is exactly what happens:

TL;DR

Sleuth overrides the log level pattern and adds tracing info into it:

map.put("logging.pattern.level", "%5p [${spring.zipkin.service.name:" + "${spring.application.name:}},%X{traceId:-},%X{spanId:-}]");

Grajeda

Thank you for the walk-through. I was able to walk until logback part you mention. IMO side effect of TraceEnvironmentPostProcessor is hard to link to. Now it all make sense why it works with logback and why it doesn't with log4j2. Javadoc for logging.pattern.level says Appender pattern for log level. Supported only with the default Logback setup. – Kiyohara

thanks this helped me debug my issue with logs missing trace info. Side-bar to @Gimpy: if asking people to explain 'how it works' based on their better knowledge of the source code vs reading and understanding the full source code ourselves is 'unethical' then we might as well ban all OSS-related questions from SO now. – Hurlyburly

Answer 2

In order to bring this back to Spring Boot 3.0 where Sleuth is no longer provided. The TraceEnvironmentPostProcessor has to be copied along with having an entry in META-INF/spring.factories

Here's the code I modified slightly from the original to make it pass SonarLint.

import java.util.HashMap;
import java.util.Map;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.env.EnvironmentPostProcessor;
import org.springframework.core.env.ConfigurableEnvironment;
import org.springframework.core.env.MapPropertySource;

class TraceEnvironmentPostProcessor implements EnvironmentPostProcessor {

  private static final String DEFAULT_PROPERTIES_SOURCE_NAME = "defaultProperties";

  @Override
  public void postProcessEnvironment(
      final ConfigurableEnvironment environment, final SpringApplication application) {

    final Map<String, Object> map = new HashMap<>();
    final boolean sleuthEnabled =
        environment.getProperty("spring.sleuth.enabled", Boolean.class, true);
    final boolean sleuthDefaultLoggingPatternEnabled =
        environment.getProperty(
            "spring.sleuth.default-logging-pattern-enabled", Boolean.class, true);
    if (sleuthEnabled && sleuthDefaultLoggingPatternEnabled) {
      map.put(
          "logging.pattern.level",
          "%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}]");
      String neverRefreshables =
          environment.getProperty(
              "spring.cloud.refresh.never-refreshable", "com.zaxxer.hikari.HikariDataSource");
      map.put(
          "spring.cloud.refresh.never-refreshable",
          neverRefreshables
              + ",org.springframework.cloud.sleuth.instrument.jdbc.DataSourceWrapper");
    }
    final var propertySources = environment.getPropertySources();

    if (propertySources.contains(DEFAULT_PROPERTIES_SOURCE_NAME)) {
      final var source = propertySources.get(DEFAULT_PROPERTIES_SOURCE_NAME);
      if (source instanceof MapPropertySource target) {
        map.entrySet().stream()
            .filter(e -> !(target.containsProperty(e.getKey())))
            .forEach(e -> target.getSource().put(e.getKey(), e.getValue()));
      }
    } else {
      propertySources.addLast(new MapPropertySource(DEFAULT_PROPERTIES_SOURCE_NAME, map));
    }
  }
}

And

org.springframework.boot.env.EnvironmentPostProcessor=\
net.trajano.swarm.logging.autoconfig.TraceEnvironmentPostProcessor

Madrepore

Answer 3

Create logback-spring.xml file inside /src/main/resources folder and setup appender.

Full logback configuration from documentation : https://github.com/spring-cloud-samples/sleuth-documentation-apps/blob/main/service1/src/main/resources/logback-spring.xml

<!-- Appender to log to file in a JSON format -->
<appender name="logstash" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOG_FILE}.json</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${LOG_FILE}.json.%d{yyyy-MM-dd}.gz</fileNamePattern>
        <maxHistory>7</maxHistory>
    </rollingPolicy>
    <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
        <providers>
            <timestamp>
                <timeZone>UTC</timeZone>
            </timestamp>
            <pattern>
                <pattern>
                    {
                    "timestamp": "@timestamp",
                    "severity": "%level",
                    "service": "${springAppName:-}",
                    "trace": "%X{traceId:-}",
                    "span": "%X{spanId:-}",
                    "baggage": "%X{key:-}",
                    "pid": "${PID:-}",
                    "thread": "%thread",
                    "class": "%logger{40}",
                    "rest": "%message"
                    }
                </pattern>
            </pattern>
        </providers>
    </encoder>
</appender>

Aerophagia