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

Answer 1

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>

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

Answer 3

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