Spring Cloud Sleuth в монолитном приложении

1. Обзор

В этой статье мы представляем Spring Cloud Sleuth — мощный инструмент для улучшения журналов в любом приложении, но особенно в системе, состоящей из нескольких сервисов.

И в этой статье мы сосредоточимся на использовании Sleuth в монолитном приложении, а не в микросервисах .

У всех нас был неудачный опыт диагностики проблемы с запланированной задачей, многопоточной операцией или сложным веб-запросом. Часто, даже при ведении журнала, трудно сказать, какие действия необходимо сопоставить друг с другом, чтобы создать один запрос.

Это может сделать диагностику сложного действия очень сложной или даже невозможной. Часто это приводит к таким решениям, как передача уникального идентификатора каждому методу в запросе для идентификации журналов.

Входит Сыщик . Эта библиотека позволяет идентифицировать журналы, относящиеся к конкретному заданию, потоку или запросу. Sleuth легко интегрируется с системами ведения журналов, такими как Logback и SLF4J , чтобы добавлять уникальные идентификаторы, помогающие отслеживать и диагностировать проблемы с помощью журналов.

Давайте посмотрим, как это работает.

2. Настройка

Мы начнем с создания веб-проекта Spring Boot в нашей любимой среде IDE и добавления этой зависимости в наш файл pom.xml :

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

Наше приложение работает с Spring Boot , а родительский pom предоставляет версии для каждой записи. Последнюю версию этой зависимости можно найти здесь: spring-cloud-starter-sleuth . Чтобы увидеть весь POM, проверьте проект на Github .

Кроме того, давайте добавим имя приложения, чтобы указать Sleuth идентифицировать журналы этого приложения.

В нашем файле application.properties добавьте эту строку:

spring.application.name=ForEach Sleuth Tutorial

3. Конфигурации сыщика

Sleuth способен улучшать журналы во многих ситуациях. Начиная с версии 2.0.0, Spring Cloud Sleuth использует Brave в качестве библиотеки трассировки, которая добавляет уникальные идентификаторы к каждому веб-запросу, поступающему в наше приложение. Кроме того, команда Spring добавила поддержку обмена этими идентификаторами между потоками.

О трассировках можно думать как об одном запросе или задании, запускаемом в приложении. Все различные шаги в этом запросе, даже между приложениями и потоками, будут иметь один и тот же traceId.

Промежутки, с другой стороны, можно рассматривать как разделы задания или запроса. Одна трассировка может состоять из нескольких диапазонов, каждый из которых соответствует определенному шагу или разделу запроса. Используя идентификаторы трассировки и интервала, мы можем точно определить, когда и где находится наше приложение, когда оно обрабатывает запрос. Чтение наших журналов стало намного проще.

В наших примерах мы рассмотрим эти возможности в одном приложении.

3.1. Простой веб-запрос

Во-первых, давайте создадим класс контроллера, который будет точкой входа для работы:

@RestController
public class SleuthController {

    @GetMapping("/")
    public String helloSleuth() {
        logger.info("Hello Sleuth");
        return "success";
    }
}

Давайте запустим наше приложение и перейдем к «http://localhost:8080». Посмотрите журналы для вывода, который выглядит так:

2017-01-10 22:36:38.254  INFO 
  [ForEach Sleuth Tutorial,4e30f7340b3fb631,4e30f7340b3fb631,false] 12516 
  --- [nio-8080-exec-1] c.b.spring.session.SleuthController : Hello Sleuth

Это выглядит как обычный журнал, за исключением части в начале между скобками. Это основная информация, которую добавил Spring Sleuth . Эти данные имеют следующий формат:

[имя приложения, traceId, spanId, экспорт]

• Имя приложения — это имя, которое мы установили в файле свойств, и его можно использовать для объединения журналов из нескольких экземпляров одного и того же приложения.
• TraceId — это идентификатор, который назначается отдельному запросу, заданию или действию. Что-то вроде того, что каждый уникальный веб-запрос, инициированный пользователем, будет иметь свой собственный traceId .
• SpanId — отслеживает единицу работы. Подумайте о запросе, который состоит из нескольких шагов. Каждый шаг может иметь свой собственный spanId и отслеживаться индивидуально. По умолчанию любой поток приложения будет начинаться с одинаковыми идентификаторами TraceId и SpanId.
• Экспорт — это логическое свойство, указывающее, был ли этот журнал экспортирован в агрегатор, такой как Zipkin . Zipkin выходит за рамки этой статьи, но играет важную роль в анализе логов, созданных Sleuth .

К настоящему времени вы должны иметь некоторое представление о возможностях этой библиотеки. Давайте рассмотрим еще один пример, чтобы продемонстрировать, насколько эта библиотека неотъемлема от ведения журнала.

3.2. Простой веб-запрос с доступом к сервису

Начнем с создания службы с помощью одного метода:

@Service
public class SleuthService {

    public void doSomeWorkSameSpan() {
        Thread.sleep(1000L);
        logger.info("Doing some work");
    }
}

Теперь давайте внедрим наш сервис в наш контроллер и добавим метод сопоставления запросов, который обращается к нему:

@Autowired
private SleuthService sleuthService;
    
    @GetMapping("/same-span")
    public String helloSleuthSameSpan() throws InterruptedException {
        logger.info("Same Span");
        sleuthService.doSomeWorkSameSpan();
        return "success";
}

Наконец, перезапустите приложение и перейдите по адресу «http://localhost:8080/same-span». Следите за выводом журнала, который выглядит следующим образом:

2017-01-10 22:51:47.664  INFO 
  [ForEach Sleuth Tutorial,b77a5ea79036d5b9,b77a5ea79036d5b9,false] 12516 
  --- [nio-8080-exec-3] c.b.spring.session.SleuthController      : Same Span
2017-01-10 22:51:48.664  INFO 
  [ForEach Sleuth Tutorial,b77a5ea79036d5b9,b77a5ea79036d5b9,false] 12516 
  --- [nio-8080-exec-3] c.foreach.spring.session.SleuthService  : Doing some work

Обратите внимание, что идентификаторы трассировки и диапазона одинаковы в двух журналах, хотя сообщения исходят из двух разных классов. Это упрощает идентификацию каждого журнала во время запроса путем поиска идентификатора трассировки этого запроса.

Это поведение по умолчанию, один запрос получает один traceId и spanId . Но мы можем вручную добавлять интервалы по своему усмотрению. Давайте рассмотрим пример, использующий эту функцию.

3.3. Добавление диапазона вручную

Для начала добавим новый контроллер:

@GetMapping("/new-span")
public String helloSleuthNewSpan() {
    logger.info("New Span");
    sleuthService.doSomeWorkNewSpan();
    return "success";
}

А теперь давайте добавим новый метод внутри нашего сервиса:

@Autowired
private Tracer tracer;
// ...
public void doSomeWorkNewSpan() throws InterruptedException {
    logger.info("I'm in the original span");

    Span newSpan = tracer.nextSpan().name("newSpan").start();
    try (SpanInScope ws = tracer.withSpanInScope(newSpan.start())) {
        Thread.sleep(1000L);
        logger.info("I'm in the new span doing some cool work that needs its own span");
    } finally {
        newSpan.finish();
    }

    logger.info("I'm in the original span");
}

Обратите внимание, что мы также добавили новый объект Tracer . Экземпляр трассировщика создается Spring Sleuth во время запуска и становится доступным для нашего класса посредством внедрения зависимостей.

Трассировки необходимо запускать и останавливать вручную. Для этого код, который выполняется в созданном вручную диапазоне , помещается внутрь блока try-finally , чтобы обеспечить закрытие диапазона независимо от успеха операции. Также обратите внимание, что новый диапазон должен быть помещен в область видимости.

Перезапустите приложение и перейдите по адресу «http://localhost:8080/new-span». Следите за выводом журнала, который выглядит следующим образом:

2017-01-11 21:07:54.924  
  INFO [ForEach Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516 
  --- [nio-8080-exec-6] c.b.spring.session.SleuthController      : New Span
2017-01-11 21:07:54.924  
  INFO [ForEach Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516 
  --- [nio-8080-exec-6] c.foreach.spring.session.SleuthService  : 
  I'm in the original span
2017-01-11 21:07:55.924  
  INFO [ForEach Sleuth Tutorial,9cdebbffe8bbbade,1e706f252a0ee9c2,false] 12516 
  --- [nio-8080-exec-6] c.foreach.spring.session.SleuthService  : 
  I'm in the new span doing some cool work that needs its own span
2017-01-11 21:07:55.924  
  INFO [ForEach Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516 
  --- [nio-8080-exec-6] c.foreach.spring.session.SleuthService  : 
  I'm in the original span

Мы видим, что третий журнал имеет такой же traceId , как и остальные, но имеет уникальный spanId . Это можно использовать для поиска разных разделов в одном запросе для более детальной трассировки.

Теперь давайте посмотрим на поддержку потоков в Sleuth .

3.4. Объединение Runnables

Чтобы продемонстрировать возможности потоковой передачи Sleuth , давайте сначала добавим класс конфигурации для настройки пула потоков:

@Configuration
public class ThreadConfig {

    @Autowired
    private BeanFactory beanFactory;

    @Bean
    public Executor executor() {
        ThreadPoolTaskExecutor threadPoolTaskExecutor
         = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(1);
        threadPoolTaskExecutor.setMaxPoolSize(1);
        threadPoolTaskExecutor.initialize();

        return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
    }
}

Здесь важно отметить использование LazyTraceExecutor . Этот класс происходит из библиотеки Sleuth и представляет собой особый тип исполнителя, который будет распространять наши traceId на новые потоки и создавать новые spanId в процессе.

Теперь давайте подключим этот исполнитель к нашему контроллеру и используем его в новом методе сопоставления запросов:

@Autowired
private Executor executor;
    
    @GetMapping("/new-thread")
    public String helloSleuthNewThread() {
        logger.info("New Thread");
        Runnable runnable = () -> {
            try {
                Thread.sleep(1000L);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            logger.info("I'm inside the new thread - with a new span");
        };
        executor.execute(runnable);

        logger.info("I'm done - with the original span");
        return "success";
}

Создав исполняемый файл, давайте перезапустим наше приложение и перейдем к «http://localhost:8080/new-thread». Следите за выводом журнала, который выглядит следующим образом:

2017-01-11 21:18:15.949  
  INFO [ForEach Sleuth Tutorial,96076a78343c364d,96076a78343c364d,false] 12516 
  --- [nio-8080-exec-9] c.b.spring.session.SleuthController      : New Thread
2017-01-11 21:18:15.950  
  INFO [ForEach Sleuth Tutorial,96076a78343c364d,96076a78343c364d,false] 12516 
  --- [nio-8080-exec-9] c.b.spring.session.SleuthController      : 
  I'm done - with the original span
2017-01-11 21:18:16.953  
  INFO [ForEach Sleuth Tutorial,96076a78343c364d,e3b6a68013ddfeea,false] 12516 
  --- [lTaskExecutor-1] c.b.spring.session.SleuthController      : 
  I'm inside the new thread - with a new span

Как и в предыдущем примере, мы видим, что все журналы имеют один и тот же traceId . Но журнал, поступающий от runnable, имеет уникальный диапазон, который будет отслеживать работу, выполненную в этом потоке. Помните, что это происходит из-за LazyTraceExecutor , если бы мы использовали обычный исполнитель, мы бы продолжали видеть тот же spanId, используемый в новом потоке.

Теперь давайте рассмотрим поддержку Sleuth методов @Async .

3.5. @Асинхронная поддержка

Чтобы добавить поддержку асинхронности, давайте сначала изменим наш класс ThreadConfig , чтобы включить эту функцию:

@Configuration
@EnableAsync
public class ThreadConfig extends AsyncConfigurerSupport {
    
    //...
    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(1);
        threadPoolTaskExecutor.setMaxPoolSize(1);
        threadPoolTaskExecutor.initialize();

        return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
    }
}

Обратите внимание, что мы расширяем AsyncConfigurerSupport , чтобы указать наш асинхронный исполнитель, и используем LazyTraceExecutor , чтобы обеспечить правильное распространение идентификаторов traceId и spanId. Мы также добавили @EnableAsync в начало нашего класса.

Теперь добавим в наш сервис асинхронный метод:

@Async
public void asyncMethod() {
    logger.info("Start Async Method");
    Thread.sleep(1000L);
    logger.info("End Async Method");
}

Теперь давайте вызовем этот метод из нашего контроллера:

@GetMapping("/async")
public String helloSleuthAsync() {
    logger.info("Before Async Method Call");
    sleuthService.asyncMethod();
    logger.info("After Async Method Call");
    
    return "success";
}

Наконец, давайте перезапустим наш сервис и перейдем к «http://localhost:8080/async». Следите за выводом журнала, который выглядит следующим образом:

2017-01-11 21:30:40.621  
  INFO [ForEach Sleuth Tutorial,c187f81915377fff,c187f81915377fff,false] 10072 
  --- [nio-8080-exec-2] c.b.spring.session.SleuthController      : 
  Before Async Method Call
2017-01-11 21:30:40.622  
  INFO [ForEach Sleuth Tutorial,c187f81915377fff,c187f81915377fff,false] 10072 
  --- [nio-8080-exec-2] c.b.spring.session.SleuthController      : 
  After Async Method Call
2017-01-11 21:30:40.622  
  INFO [ForEach Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072 
  --- [lTaskExecutor-1] c.foreach.spring.session.SleuthService  : 
  Start Async Method
2017-01-11 21:30:41.622  
  INFO [ForEach Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072 
  --- [lTaskExecutor-1] c.foreach.spring.session.SleuthService  : 
  End Async Method

Здесь мы видим, что, как и в нашем работоспособном примере, Sleuth распространяет traceId в асинхронный метод и добавляет уникальный spanId.

Давайте теперь рассмотрим пример, используя поддержку spring для запланированных задач.

3.6. @Запланированная поддержка

Наконец, давайте посмотрим, как Sleuth работает с методами @Scheduled . Для этого давайте обновим наш класс ThreadConfig , чтобы включить планирование:

@Configuration
@EnableAsync
@EnableScheduling
public class ThreadConfig extends AsyncConfigurerSupport
  implements SchedulingConfigurer {
 
    //...
    
    @Override
    public void configureTasks(ScheduledTaskRegistrar scheduledTaskRegistrar) {
        scheduledTaskRegistrar.setScheduler(schedulingExecutor());
    }

    @Bean(destroyMethod = "shutdown")
    public Executor schedulingExecutor() {
        return Executors.newScheduledThreadPool(1);
    }
}

Обратите внимание, что мы реализовали интерфейс SchedulingConfigurer и переопределили его метод configureTasks. Мы также добавили @EnableScheduling в начало нашего класса.

Далее давайте добавим сервис для наших запланированных задач:

@Service
public class SchedulingService {

    private Logger logger = LoggerFactory.getLogger(this.getClass());
 
    @Autowired
    private SleuthService sleuthService;

    @Scheduled(fixedDelay = 30000)
    public void scheduledWork() throws InterruptedException {
        logger.info("Start some work from the scheduled task");
        sleuthService.asyncMethod();
        logger.info("End work from scheduled task");
    }
}

В этом классе мы создали одно запланированное задание с фиксированной задержкой в 30 секунд.

Давайте теперь перезапустим наше приложение и дождемся выполнения нашей задачи. Следите за выводом в консоли следующим образом:

2017-01-11 21:30:58.866  
  INFO [ForEach Sleuth Tutorial,3605f5deaea28df2,3605f5deaea28df2,false] 10072 
  --- [pool-1-thread-1] c.b.spring.session.SchedulingService     : 
  Start some work from the scheduled task
2017-01-11 21:30:58.866  
  INFO [ForEach Sleuth Tutorial,3605f5deaea28df2,3605f5deaea28df2,false] 10072 
  --- [pool-1-thread-1] c.b.spring.session.SchedulingService     : 
  End work from scheduled task

Здесь мы видим, что Sleuth создал новые идентификаторы трассировки и диапазона для нашей задачи. Каждый экземпляр задачи по умолчанию получит собственную трассировку и диапазон.

4. Вывод

В заключение мы увидели, как Spring Sleuth можно использовать в различных ситуациях внутри одного веб-приложения. Мы можем использовать эту технологию, чтобы легко сопоставлять журналы из одного запроса, даже если этот запрос охватывает несколько потоков.

Теперь мы видим, как Spring Cloud Sleuth может помочь нам сохранить здравомыслие при отладке многопоточной среды. Идентифицируя каждую операцию в traceId и каждый шаг в spanId , мы действительно можем начать разбивать наш анализ сложных заданий в наших журналах.

Даже если мы не перейдем к облаку, Spring Sleuth , вероятно, будет критически важной зависимостью практически в любом проекте; его легко интегрировать, и он представляет собой огромную добавленную стоимость .

Отсюда вы можете исследовать другие возможности Sleuth . Он может поддерживать трассировку в распределенных системах с использованием RestTemplate , через протоколы обмена сообщениями, используемые RabbitMQ и Redis , и через шлюз, такой как Zuul.

Как всегда, вы можете найти исходный код на Github .