Spring Cloud Sleuth in un'applicazione Monolith

1. Panoramica

In questo articolo, stiamo introducendo Spring Cloud Sleuth , un potente strumento per migliorare i registri in qualsiasi applicazione, ma soprattutto in un sistema costituito da più servizi.

E per questo articolo ci concentreremo sull'utilizzo di Sleuth in un'applicazione monolite, non tra i microservizi .

Abbiamo tutti avuto la sfortunata esperienza di provare a diagnosticare un problema con un'attività pianificata, un'operazione multi-thread o una richiesta web complessa. Spesso, anche quando è presente la registrazione, è difficile dire quali azioni devono essere correlate insieme per creare una singola richiesta.

Ciò può rendere la diagnosi di un'azione complessa molto difficile o addirittura impossibile. Spesso danno luogo a soluzioni come il passaggio di un ID univoco a ciascun metodo nella richiesta per identificare i log.

Arriva Sleuth . Questa libreria consente di identificare i log relativi a uno specifico lavoro, thread o richiesta. Sleuth si integra facilmente con framework di registrazione come Logback e SLF4J per aggiungere identificatori univoci che aiutano a tracciare e diagnosticare i problemi utilizzando i log.

Diamo un'occhiata a come funziona.

2. Configurazione

Inizieremo creando un progetto web Spring Boot nel nostro IDE preferito e aggiungendo questa dipendenza al nostro file pom.xml :

 org.springframework.cloud spring-cloud-starter-sleuth 

La nostra applicazione funziona con Spring Boot e il pom genitore fornisce le versioni per ogni voce. L'ultima versione di questa dipendenza può essere trovata qui: spring-cloud-starter-sleuth. Per vedere l'intero POM controlla il progetto su Github.

Inoltre, aggiungiamo un nome di applicazione per istruire Sleuth a identificare i log di questa applicazione.

Nel nostro file application.properties aggiungi questa riga:

spring.application.name=Baeldung Sleuth Tutorial

3. Configurazioni Sleuth

Sleuth è in grado di migliorare i registri in molte situazioni. A partire dalla versione 2.0.0, Spring Cloud Sleuth utilizza Brave come libreria di tracciamento che aggiunge ID univoci a ogni richiesta web che entra nella nostra applicazione. Inoltre, il team di Spring ha aggiunto il supporto per la condivisione di questi ID oltre i confini dei thread.

Le tracce possono essere pensate come una singola richiesta o lavoro che viene attivato in un'applicazione. Tutti i vari passaggi in quella richiesta, anche attraverso i limiti dell'applicazione e del thread, avranno lo stesso traceId.

Gli intervalli, d'altra parte, possono essere pensati come sezioni di un lavoro o di una richiesta. Una singola traccia può essere composta da più intervalli, ciascuno correlato a uno specifico passaggio o sezione della richiesta. Usando gli id ​​di traccia e span possiamo individuare esattamente quando e dove si trova la nostra applicazione mentre elabora una richiesta. Rendere la lettura dei nostri log molto più semplice.

Nei nostri esempi, esploreremo queste capacità in una singola applicazione.

3.1. Richiesta web semplice

Per prima cosa, creiamo una classe controller che sia un punto di ingresso con cui lavorare:

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

Eseguiamo la nostra applicazione e andiamo a "// localhost: 8080". Guarda i log per l'output che assomiglia a:

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

Sembra un normale registro, tranne per la parte all'inizio tra parentesi. Queste sono le informazioni fondamentali che Spring Sleuth ha aggiunto. Questi dati seguono il formato di:

[nome applicazione, traceId, spanId, export]

  • Nome applicazione : questo è il nome che abbiamo impostato nel file delle proprietà e può essere utilizzato per aggregare i registri di più istanze della stessa applicazione.
  • TraceId : questo è un ID assegnato a una singola richiesta, lavoro o azione. Qualcosa come ogni richiesta web avviata da un utente univoco avrà il proprio traceId .
  • SpanId : tiene traccia di un'unità di lavoro. Pensa a una richiesta che consiste in più passaggi. Ogni passaggio può avere il proprio spanId ed essere monitorato individualmente. Per impostazione predefinita, qualsiasi flusso dell'applicazione inizierà con gli stessi TraceId e SpanId.
  • Esporta : questa proprietà è un valore booleano che indica se questo registro è stato esportato o meno in un aggregatore come Zipkin . Zipkin va oltre lo scopo di questo articolo, ma gioca un ruolo importante nell'analisi dei log creati da Sleuth .

A questo punto, dovresti avere un'idea del potere di questa libreria. Diamo un'occhiata a un altro esempio per dimostrare ulteriormente quanto sia integrante questa libreria per la registrazione.

3.2. Richiesta Web semplice con accesso al servizio

Cominciamo creando un servizio con un unico metodo:

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

Ora inseriamo il nostro servizio nel nostro controller e aggiungiamo un metodo di mappatura delle richieste che lo accede:

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

Infine, riavvia l'applicazione e vai a "// localhost: 8080 / same-span". Guarda l'output del log che assomiglia a:

2017-01-10 22:51:47.664 INFO [Baeldung 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 [Baeldung Sleuth Tutorial,b77a5ea79036d5b9,b77a5ea79036d5b9,false] 12516 --- [nio-8080-exec-3] c.baeldung.spring.session.SleuthService : Doing some work

Tieni presente che gli ID di traccia e di intervallo sono gli stessi tra i due log anche se i messaggi provengono da due classi diverse. Ciò rende banale identificare ogni registro durante una richiesta cercando il traceId di quella richiesta.

Questo è il comportamento predefinito, una richiesta ottiene un unico traceId e spanId . Ma possiamo aggiungere manualmente gli intervalli come riteniamo opportuno. Diamo un'occhiata a un esempio che utilizza questa funzionalità.

3.3. Aggiunta manuale di un intervallo

Per iniziare, aggiungiamo un nuovo controller:

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

E ora aggiungiamo il nuovo metodo all'interno del nostro servizio:

@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"); }

Note that we also added a new object, Tracer. The tracer instance is created by Spring Sleuth during startup and is made available to our class through dependency injection.

Traces must be manually started and stopped. To accomplish this, code that runs in a manually created span is placed inside a try-finally block to ensure the span is closed regardless of the operation's success. Also, notice that new span has to be placed in scope.

Restart the application and navigate to “//localhost:8080/new-span”. Watch for the log output that looks like:

2017-01-11 21:07:54.924 INFO [Baeldung 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 [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516 --- [nio-8080-exec-6] c.baeldung.spring.session.SleuthService : I'm in the original span 2017-01-11 21:07:55.924 INFO [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,1e706f252a0ee9c2,false] 12516 --- [nio-8080-exec-6] c.baeldung.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 [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516 --- [nio-8080-exec-6] c.baeldung.spring.session.SleuthService : I'm in the original span

We can see that the third log shares the traceId with the others, but it has a unique spanId. This can be used to locate different sections in a single request for more fine-grained tracing.

Now let's take a look at Sleuth's support for threads.

3.4. Spanning Runnables

To demonstrate the threading capabilities of Sleuth let's first add a configuration class to set up a thread pool:

@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); } }

It is important to note here the use of LazyTraceExecutor. This class comes from the Sleuth library and is a special kind of executor that will propagate our traceIds to new threads and create new spanIds in the process.

Now let's wire this executor into our controller and use it in a new request mapping method:

@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"; }

With our runnable in place, let's restart our application and navigate to “//localhost:8080/new-thread”. Watch for log output that looks like:

2017-01-11 21:18:15.949 INFO [Baeldung 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 [Baeldung 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 [Baeldung Sleuth Tutorial,96076a78343c364d,e3b6a68013ddfeea,false] 12516 --- [lTaskExecutor-1] c.b.spring.session.SleuthController : I'm inside the new thread - with a new span

Much like the previous example we can see that all the logs share the same traceId. But the log coming from the runnable has a unique span that will track the work done in that thread. Remember that this happens because of the LazyTraceExecutor, if we were to use a normal executor we would continue to see the same spanId used in the new thread.

Now let's look into Sleuth's support for @Async methods.

3.5. @Async Support

To add async support let's first modify our ThreadConfig class to enable this feature:

@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); } }

Note that we extend AsyncConfigurerSupport to specify our async executor and use LazyTraceExecutor to ensure traceIds and spanIds are propagated correctly. We have also added @EnableAsync to the top of our class.

Let's now add an async method to our service:

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

Now let's call into this method from our controller:

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

Finally, let's restart our service and navigate to “//localhost:8080/async”. Watch for the log output that looks like:

2017-01-11 21:30:40.621 INFO [Baeldung 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 [Baeldung 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 [Baeldung Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072 --- [lTaskExecutor-1] c.baeldung.spring.session.SleuthService : Start Async Method 2017-01-11 21:30:41.622 INFO [Baeldung Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072 --- [lTaskExecutor-1] c.baeldung.spring.session.SleuthService : End Async Method

We can see here that much like our runnable example, Sleuth propagates the traceId into the async method and adds a unique spanId.

Let's now work through an example using spring support for scheduled tasks.

3.6. @Scheduled Support

Finally, let's look at how Sleuth works with @Scheduled methods. To do this let's update our ThreadConfig class to enable scheduling:

@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); } }

Note that we have implemented the SchedulingConfigurer interface and overridden its configureTasks method. We have also added @EnableScheduling to the top of our class.

Next, let's add a service for our scheduled tasks:

@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"); } }

In this class, we have created a single scheduled task with a fixed delay of 30 seconds.

Let's now restart our application and wait for our task to be executed. Watch the console for output like this:

2017-01-11 21:30:58.866 INFO [Baeldung 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 [Baeldung Sleuth Tutorial,3605f5deaea28df2,3605f5deaea28df2,false] 10072 --- [pool-1-thread-1] c.b.spring.session.SchedulingService : End work from scheduled task

We can see here that Sleuth has created new trace and span ids for our task. Each instance of a task will get it's own trace and span by default.

4. Conclusion

In conclusion, we have seen how Spring Sleuth can be used in a variety of situations inside a single web application. We can use this technology to easily correlate logs from a single request, even when that request spans multiple threads.

By now we can see how Spring Cloud Sleuth can help us keep our sanity when debugging a multi-threaded environment. By identifying each operation in a traceId and each step in a spanId we can really begin to break down our analysis of complex jobs in our logs.

Anche se non andiamo al cloud, Spring Sleuth è probabilmente una dipendenza critica in quasi tutti i progetti; è semplice da integrare ed è un'enorme aggiunta di valore .

Da qui potresti voler indagare su altre caratteristiche di Sleuth . Può supportare la traccia in sistemi distribuiti utilizzando RestTemplate , attraverso i protocolli di messaggistica usati da RabbitMQ e Redis e attraverso un gateway come Zuul.

Come sempre puoi trovare il codice sorgente su Github.