How spring cloud sleuth adds 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

As documented? docs.spring.io/spring-cloud-sleuth/docs/current-SNAPSHOT/… — Gimby
I saw the documentation but it doesn't contain more details, so I'm interested in those details. — Patrik Mihalčin
Either you dig in the source code to figure out how Sleuth does something, or someone else does it for you. The more ethical approach would be that you do it yourself rather than wait for someone to hand it to you. Curiosity is not a valid reason to ask an unresearched question, the answer to this is not very likely going to be helpful to other people. — Gimby
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. — Patrik Mihalčin

Jonatan Ivanov Jonatan Ivanov · Accepted Answer · 2021-01-22T19:01:13

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

How spring cloud sleuth adds tracing information to logback log lines

1 Answers

TL;DR