Логирование в Spring Boot с глобальным traceId (применяем Logback и Spring Cloud Sleuth)

Предположим, нам необходимо по логам всех взаимодействующих друг с другом микросервисов отследить всю историю активности, которая привела к ошибке, начиная от REST-запроса с UI к микросервису A и заканчивая логированием ошибки "соседним" микросервисом B, к которому обратился сервис A.
С этой целью может быть использован так называемый TraceId - специальный глобальный ID, который автоматически будет добавлен логером в логируемое сообщение в любом месте, где мы пожелаем это сделать.

В моем проекте была поставлена следующая задача: сервис получает вместе с REST-запросом TraceId, который был присвоен потоку извне (например, nginx или другой сервис), и добавляет его в логируемые сообщения и в свои REST-запросы к другим сервисам.

Spring Cloud Sleuth предлагает необходимый функционал "из коробки". Что для этого нужно:

1\ Добавляем зависимость в pom.xml

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
    <version>${spring-cloud-starter-sleuth.version}</version>
</dependency>

2\ Указываем имя нашего приложения в файле bootstrap.yml

spring:
  application:
    name: demo.sleuth

Зачем приложению имя? Оно будет добавлено в логируемое сообщение. Наличие имени - не обязательно. Можно обойтись и без него.
Почему указываем имя в bootstrap.yml? Потому что при использовании компонентов Spring Cloud предполагается, что конфигурация приложения находится именно в этом файле. Я пробовал указывать имя файла в application.properties и application.yml, но Spring Cloud Sleuth его там "не видел".

3\ Добавляем файл конфигурации logback-spring.xml

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

    <property name="LOG_FILE" value="log/demo.sleuth"/>​
    <property name="CONSOLE_LOG_PATTERN"
              value="%clr(%d{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}"/>
    <property name="FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS} ${LOG_LEVEL_PATTERN:-%5p} ${PID:- } --- [%15.15t] %-40.40logger{39} : %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}" />

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${LOG_FILE}.log</File>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.log</FileNamePattern>
            <MaxHistory>7</MaxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="FILE"/>
        <appender-ref ref="CONSOLE"/>
    </root>

</configuration>

4\ Запускаем проиложение и в терминале направляем ему GET-запрос на адрес http://localhost:8080/hello

curl http://localhost:8080/hello

В ответ получаем сообщение "Hello" и видим следующие логи:

2019-01-18 12:27:01.451  INFO [demo.sleuth,,,] 9442 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2019-01-18 12:27:01.752  INFO [demo.sleuth,,,] 9442 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2019-01-18 12:27:01.753  INFO [demo.sleuth,,,] 9442 --- [           main] r.e.demosleuth.DemoSleuthApplication     : Started DemoSleuthApplication in 2.132 seconds (JVM running for 2.497)
2019-01-18 12:27:12.215  INFO [demo.sleuth,,,] 9442 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2019-01-18 12:27:12.215  INFO [demo.sleuth,,,] 9442 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2019-01-18 12:27:12.224  INFO [demo.sleuth,,,] 9442 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 9 ms
2019-01-18 12:27:19.547  INFO [demo.sleuth,092c5c8569eb8bd6,092c5c8569eb8bd6,false] 9442 --- [nio-8080-exec-2] r.e.demosleuth.controller.MyController   : Called getHello

Записи в логе имеют вид [appname,traceId,spanId,exportable], где:
- appname - имя приложения;
- traceId - ID графа;
- spanId - ID отдельной операции в графе;
- exportable - ключ, который устанавливает, нужно ли экспортировать запись в Zipkin.
 TraceId и spanId - это 64-битные числа (тип long), представленные в шестнадцатеричном формате.

Spring Cloud Sleuth проверяет в поступившем REST-запросе наличие заголовков X-B3-TraceId и X-B3-SpanId и при их отсутствии генерирует значения traceId и spanId самостоятельно. В этом случае traceId и spanId будут одинакоывми, т.к. это будет первый span в этом trace.

5\ Направим приложению REST-запрос с заголовками X-B3-TraceId и X-B3-SpanId

curl -H "X-B3-TraceId: 6bfd228dc00d216b" -H "X-B3-SpanId: 46ab0d418373cbc9" http://localhost:8080/hello 

В ответ получим сообщение "Hello!" и  увидим следующий лог:

2019-01-18 13:10:33.972  INFO [demo.sleuth,6bfd228dc00d216b,46ab0d418373cbc9,false] 12297 --- [nio-8080-exec-3] r.e.demosleuth.controller.MyController   : Called getHello

В нём видим, что Sleuth распознал и применил заданные нами traceId и spanId.

Код на GitHub.