Spring sleuth with SpringBoot (log correlation) - Traceid & SpanId Not displayed

Question

I have an existing Spring boot (2.2.0) application and trying to integrate Spring cloud sleuth to get automatic trace and span id. The logback file is as follows -

<configuration>

<property name="LOGS" value="./logs" />

<appender name="Console"
          class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
        <Pattern>
            %black(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] %yellow(%C{1.}): %msg%n%throwable
        </Pattern>
    </layout>
</appender>

<appender name="RollingFile"
          class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${LOGS}/spring-boot-logger.log</file>
    <encoder
            class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
        <Pattern>%d %p %C{1.} [%t] %m%n</Pattern>
    </encoder>

    <rollingPolicy
            class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <!-- rollover daily and when the file reaches 100 MegaBytes -->
        <fileNamePattern>${LOGS}/archived/spring-boot-logger-%d{yyyy-MM-dd}.%i.log
        </fileNamePattern>
        <timeBasedFileNamingAndTriggeringPolicy
                class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
            <maxFileSize>100MB</maxFileSize>
        </timeBasedFileNamingAndTriggeringPolicy>
    </rollingPolicy>
</appender>

<!-- LOG everything at specified level level -->
<root level="info">
    <appender-ref ref="RollingFile" />
    <appender-ref ref="Console" />
</root>

This config for logback does not log/display traceId as expected.
As far as i know, nothing else is required except update to pom.xml which is as follows -

<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-sleuth</artifactId>
            <version>2.2.0.RELEASE</version>
            <type>pom</type>
            <scope>import</scope>
        </dependency>
    </dependencies>
</dependencyManagement>

and

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

Surprisingly enough, if I include following in the logback config -

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

The traceid, spanid and application name is displayed on console . Probably from the base.xml config.

Any idea what might be wrong with my logback file or any other config? Is there anything missing in the config?

Any help is appreciated.

Lied

Answer 1

Well sleuth gets traceId and spanId into logs by overwriting/extending the log-level "field" of the log-pattern (inside org.springframework.cloud.sleuth.autoconfig.TraceEnvironmentPostProcessor)

so in defaults.xml (imported in the base.xml) spring defines the pattern to be:

    <property name="CONSOLE_LOG_PATTERN" value="${CONSOLE_LOG_PATTERN:-%clr(%d{${LOG_DATEFORMAT_PATTERN:-yyyy-MM-dd HH:mm:ss.SSS}}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}}"/>

as you can see if variable LOG_LEVEL_PATTERN is defined it's the one taken (and then overwritten/extended in TraceEnvironmentPostProcessor, if not, it defaults to the default level pattern %5p

so if you do not include base.xml sleuth will not be able to "adjust" the log-level pattern as LOG_LEVEL_PATTERN then just does not exist in the pattern.

As documentation states (https://docs.spring.io/spring-boot/docs/current/reference/htmlsingle/#howto-logging) you always should include base.xml in your custom logback.xml, and you're fine.

not recommended:
try to define your log level pattern as ${LOG_LEVEL_PATTERN:-%5p} instead of just %5p or %-5level (but solution of including base.xml is the correct solution, if you'd ask me.

also:
https://docs.spring.io/spring-boot/docs/current/reference/htmlsingle/#boot-features-custom-log-configuration lists application.(properties|yml) fields to tweak spring-boot logging from properties.

e.g. I have custom BaggageFields for propagating downstream and my application.properties to see them in logfiles I define application properties as follows: (I do not define a custom logback.xml!)

for sleuth 2.0+

logging:
  pattern:
    level: "%5p [${spring.zipkin.service.name:${spring.application.name:-}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}] [%X{ddd:-},%X{bp:-},%X{bpids:-}] [%X{op:-},%X{chunk:-},%X{i:-}]"

for sleuth 3.0+

logging:
  pattern:
    level: "%5p [${spring.zipkin.service.name:${spring.application.name:}},%X{traceId:-},%X{spanId:-}] [%X{ddd:-},%X{bp:-},%X{bpids:-}] [%X{op:-},%X{chunk:-},%X{i:-}]"

Thapsus

Thanks. I have added the solution used by me. It just makes use of the default format provided under LOG_LEVEL_PATTERN. Yours is much more flexible for having a custom format. – Lied

Answer 2

In case anyone out there looking for olution I was able to get it using following changes - Add the following to you logback-spring.xml

 <conversionRule conversionWord="clr" converterClass="org.springframework.boot.logging.logback.ColorConverter" />
    <conversionRule conversionWord="wex" converterClass="org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter" />
    <conversionRule conversionWord="wEx" converterClass="org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter" />

Then use the following variable in your log pattern -

%clr(${LOG_LEVEL_PATTERN:-%5p})

E.g.: -

<Pattern>%d %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(%-40.40logger{39}) %clr([%20.20t]) %clr(:) %m%n</Pattern>

Hope this helps someone.

Lied