em
Rastro distribuído com Spring Boot e OpenTelemetry, um tutorial
OpenTelemetry (Otel) é um projeto de código aberto que fornece um conjunto padronizado de ferramentas, APIs e SDKs para observabilidade de aplicações distribuídas. Ele permite coletar, processar e exportar métricas, logs e rastros (traces) para outras ferramentas (Prometheus, Jaeger, Grafana Tempo, etc.), facilitando o monitoramento e a detecção de problemas em sistemas complexos.
Neste post vamos focar na visão de rastro distribuído que conseguimos ter em ferramentas como Jaeger graças à instrumentação realizada pelo OpenTelemetry. Para isso, veremos como instrumentar uma aplicação Spring Boot e as vantagens que daí podemos tirar.
O que não vamos cobrir aqui: conceitos básicos sobre rastro distribuído (tracing). Para isso, você pode conferir esse outro post nosso sobre rastro distribuído.
Então vamos lá!
Cenário - serviços instrumentados
Para uma boa avaliação de uma solução de rastro distribuído é preciso montar um cenário conveniente para tal análise, envolvendo pelo menos dois serviços. Montamos então um cenário com os serviços A e B seguindo o segunte fluxo:
- Quando invocado, o serviço A primeiramente faz uma pausa, simulando assim algum processamento mais demorado.
- Serviço A chama serviço B para obter um título de álbum aleatório.
- Serviço B obtém o título aleatório do banco de dados e o devolve ao serviço A.
- Serviço A obtém o álbum completo, procurando o álbum pelo título no banco de dados.
- Alguns álbuns estão duplicados na tabela. Se Serviço B retornar um título de um desses álbuns duplicados, haverá um erro interno no serviço A (o que é interessante para monitoração).
- Às vezes o serviço B também retorna um erro interno de forma aleatória (20% das vezes que é chamado). Ao receber um erro interno de B, o serviço A também responde com um erro interno.
A descrição acima está abaixo representada como um diagrama de sequência:
O código-fonte desses serviços, já com a instrumentação do OpenTelemetry, se encontra disponível em https://gitlab.com/leo-observability-labs/otel-lab.
Obs: a versão utilizada do Spring Boot é a 3.4.1.
Setup de infraestrutura - OpenTelemetry Collector e Jaeger
É possível instrumentar a aplicação Spring Boot sem alterar em nada seu código utilizando-se de um agente que é executado de forma colocada com a aplicação (isto é, o agente é um jar a parte que roda no mesmo container que a aplicação, o que também é chamado de sidecar). Mas não utilizaremos essa abordagem, alteraremos o código para fazer a instrumentação.
Uma aplicação instrumentada pode enviar dados diretamente para o que é chamado de backend, que são as diversas ferramentas que vão de fato realizar alguma apresentação aos usuários da telemetria. Mas é possível haver uma entidade de infraestrutura intermediária que é o OpenTelemetry Collector. O seu uso é recomendado e mais a frente discutiremos melhor o porquê disso. Esse Collector pode ser executado no host do serviço instrumentado ou em um servidor a parte. Em nosso caso, para a demonstração tudo será executado em localhost. Contudo, a ideia é que em produção o Collector rodaria em um host remoto dedicado.
Obs: as escolhas de instrumentar a aplicação com alteração de código e considerar o Collector em um host remoto foram feitas em funções das possibilidades mais viáveis em meu lugar de trabalho.
Por fim, para que possamos validar que a instrumentação está ocorrendo da forma desejada, precisamos de uma ferramenta de visualização. Utilizaremos aqui o Jaeger, mas sem detrimento nenhum de outras possíveis opções, como o Grafana Tempo.
Com essas considerações, a visão que temos da infraestrutura de produção envolvida no uso do OpenTelemetry é a seguinte:
Para a demonstração, o Collector e o Jaeger estarão em contêineres Docker rodando em localhost. Segue o trecho do docker-compose.yml responsável por isso:
otel-collector:
image: otel/opentelemetry-collector-contrib:0.121.0
ports:
# Aplicação instrumentada envia dados por uma das portas abaixo:
- "4317:4317" # grpc
- "4318:4318" # http
volumes:
- ./otel-collector-config.yml:/etc/otel-collector-config.yml
command: ["--config=/etc/otel-collector-config.yml"]
depends_on:
- jaeger
jaeger:
image: jaegertracing/jaeger:2.4.0
ports:
- "16686:16686" # interface web: http://localhost:16686
# Portas abaixo inibidas para não conflitar com as portas do Collector
# Obs: a exposição não é necessária para o acesso a partir de outro container
# - "4317:4317"
# - "4318:4318"
environment:
- LOG_LEVEL=debug
E aqui está o arquivo otel-collector-config.yml, que diz ao Collector para retransmitir os dados de trace ao Jaeger:
receivers:
otlp:
protocols:
grpc:
endpoint: 0.0.0.0:4317
http:
endpoint: 0.0.0.0:4318
exporters:
debug: {}
otlp/jaeger:
endpoint: "http://jaeger:4317"
tls:
insecure: true
service:
pipelines:
traces:
receivers: [otlp]
exporters: [debug, otlp/jaeger]
metrics:
receivers: [otlp]
exporters: [debug]
logs:
receivers: [otlp]
exporters: [debug]
Obs: embora estejamos interessados apenas nos traces, no arquivo acima declaramos os pipelines de metrics e logs para evitar erros na aplicação ao tentar enviar os dados de telemetria. Isso ocorre porque, por padrão, a auto instrumentação do OpenTelemetry no Spring Boot envia para o Collector os dados de rastros, métricas e logs. Deve ser possível alterar a configuração da aplicação para realizar o envio apenas dos traces, mas não exploramos essa possibilidade.
Instrumentação automática - configuração inicial
Em cada um dos projetos instrumentados (serviços A e B), realizamos a seguinte configuração:
No build.gradle:
dependencyManagement {
imports {
mavenBom("io.opentelemetry.instrumentation:opentelemetry-instrumentation-bom:2.14.0")
}
}
dependencies {
// ...
implementation("io.opentelemetry.instrumentation:opentelemetry-spring-boot-starter")
}
Essa configuração ativa a instrumentação automática, que já fornece vários benefícios:
- Envio de métricas, logs e traces para um OpenTelemetry Collector.
- Propagação de contexto: quando a aplicação instrumentada invoca outro serviço (em nosso caso, pelo
RestTemplate), o trace ID é enviado para o serviço invocado por algum header HTTP padronizado. - As consultas SQL realizadas são automaticamente coletadas.
Por padrão, a auto instrumentação enviará os dados de telemetria com o uso do protocolo gRPC para o endereço http://localhost:4317. É possível alterar o protocolo com a propriedade otel.exporter.otlp.protocol no application.properties (as opções são grpc e http/protobuf), enquanto que o endereço do Collector (para onde os dados são enviados) é configurável pela propriedade otel.exporter.otlp.endpoint. Mais detalhes na documentação de configuração do SDK do OpenTelemetry.
Visão de trace timeline no Jaeger
Na figura abaixo temos a visão de trace timeline oferecida pelo Jaeger. É por meio dessa visão que avaliaremos os recursos de instrumentação oferecidos pelo OpenTelemetry.
Invocação entre serviços
Aqui está o trecho de código do Serviço A que realiza a invocação do Serviço B (nenhuma alteração em função do Otel):
@RestController
@Log4j2
public class ServiceAController {
@Autowired
private RestTemplate restTemplate; // e aí, só usar
// ....
private String getRandomTitleFromServiceB() {
String url = "http://localhost:8092/service-b/albums/titles/random";
try {
ResponseEntity<String> response = restTemplate.getForEntity(url, String.class);
return response.getBody();
} catch (HttpStatusCodeException e) {
throw new IllegalStateException("Failed to get random album title from service B.");
}
}
}
Apenas com a configuração inicial da instrumentação, temos a propagação de contexto de um serviço para o outro, o que nos possibilita ver no mesmo trace os spans ocorridos em diferentes serviços. Além disso, o trace timeline explicita que houve uma invocação do serviço A para o serviço B, conforme figura abaixo.
Obs: a barra vertical com dois riscos na figura representa um sinal de descontinuidade. Isto é: a captura de tela original foi recortada para melhor visualização.
Temos também destacado na Figura 4 o tempo gasto com a invocação, o que pode ser útil na detecção de gargalos.
Integração com logs
No início da execução de cada um de nossos serviços, criamos um registro de log, conforme segue:
import lombok.extern.log4j.Log4j2;
@RestController
@Slf4j
public class ServiceAController {
// ...
@GetMapping("/albums/random")
public Album getRandomAlbum() {
log.info("Something quite interesting seemed to have happened here in Service A...");
Obs: ao usarmos a anotação @Slf4j do Lombok, utilizamos o Logback, que é o sistema de log mais recente, sucessor do log4j, e o padrão do Spring Boot. Por isso não recomendamos utilizar a anotação @Log4j2 do Lombok.
Para que cada registro de log fique vinculado ao correspondente span no rastro distribuído, precisamos fazer a seguinte configuração no arquivo src/main/resources/logback.xml (adicionar um appender que processará cada registro de log):
<configuration>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss} %-5level %logger Trace ID: %X{trace_id} Span ID: %X{span_id} - %msg%n</pattern>
</encoder>
</appender>
<appender name="OPENTELEMETRY" class="leo.obslab.servicea.OtelLogAppender"/>
<logger name="org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver" level="ERROR"/>
<root level="info">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="OPENTELEMETRY"/>
</root>
</configuration>
E também criar a classe OtelLogAppender, que acrescenta cada registro de log como um evento do span corrente:
import ch.qos.logback.core.AppenderBase;
import ch.qos.logback.classic.spi.ILoggingEvent;
import io.opentelemetry.api.trace.Span;
public class OtelLogAppender extends AppenderBase<ILoggingEvent> {
@Override
protected void append(ILoggingEvent event) {
Span.current().addEvent(event.getFormattedMessage());
}
}
Dessa forma, conseguimos visualizar os registros de log ocorridos nos diferentes serviços na mesma visão do trace timeline:
Com a configuração no logback.xml introduzindo trace_id e o span_id no pattern do log padrão, temos outro importante efeito que é imprimir o trace ID (e o span ID) em cada registro de log escrito pela aplicação (inclusive stack traces), conforme o exemplo abaixo:
Integração com erros - stack trace vinculado ao trace
Para que o lançamento de um erro interno seja facilmente identificado no trace e para que o stack trace também fique vinculado ao trace, é preciso capturar o erro no exception handler:
import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.StatusCode;
@ControllerAdvice
@Slf4j
public class ServiceAExceptionHandler {
@ExceptionHandler(RuntimeException.class)
public ResponseEntity<InternalErrorMessage> runtimeException(RuntimeException e, HttpServletRequest request) {
log.error("Unexpected error: " + e.getMessage(), e);
captureExceptionWithOtel(e); // aqui!
InternalErrorMessage msg = new InternalErrorMessage();
return ResponseEntity.status(HttpStatus.INTERNAL_SERVER_ERROR.value()).body(msg);
}
private void captureExceptionWithOtel(RuntimeException e) {
Span span = Span.current();
if (span != null && span.getSpanContext().isValid()) {
span.recordException(e);
span.setStatus(StatusCode.ERROR);
} else {
log.warn("No active span found to capture the exception.");
}
}
}
Dessa forma, temos o segunite resultado (uma marca no span indicando erro e o stack trace vinculado a esse span):
Trace ID nas mensagem de erro interno
Além de exibir o trace ID gerado pelo OpenTelemetry nos registros de log, é importante também retornarmos esse trace ID nas mensagens de erro interno, pois assim acionamentos podem ser abertos com o cliente nos fornecendo o trace ID (e assim conseguimos relacionar traces, logs e stack traces ao problema do cliente).
Para isso, definimos a mensagem retornada em caso de erro interno da seguinte forma:
@Data
public class InternalErrorMessage {
private final String title = "Internal Error";
private final LocalDateTime dateTime = LocalDateTime.now();
private final String traceId = TraceIdManager.getTraceId();
private final String error = "An unexpected error occurred at " + dateTime
+ ", please try again later. If the error persists, please contact your system administrator with the trace id: "
+ traceId + ".";
}
Sendo que o trace ID acima é obtida do seguinte TraceIdManager:
import io.opentelemetry.api.trace.Span;
public class TraceIdManager {
public static String getTraceId() {
Span currentSpan = io.opentelemetry.api.trace.Span.current();
return currentSpan.getSpanContext().getTraceId();
}
}
Assim, quando um erro interno estoura, o cliente tem acesso a esse trace ID, conforme o exemplo de resposta abaixo:
Consultas SQL
Apenas com a configuração inicial da instrumentação, temos a instrumentação das consultas SQL realizadas pela aplicação. Assim, cada acesso ao banco fica explícito como um span no trace, conforme figura abaixo. Uma coisa bem legal é que encontramos facilmente o código SQL executado.
Como é possível ver na figura, temos também o tempo de execução da consulta SQL, o que é muito importante para a detecção de gargalos de desempenho da aplicação.
Span personalizado
Para destacar de forma personalizada um trecho do código no trace como um span, podemos anotar o método a ser destacado com @WithSpan, conforme segue:
@Component
public class Sleeper {
@WithSpan("sleepingCustomSpan") // aqui!
public void sleepWithCustomSpan() {
try {
Thread.sleep(100);
} catch (InterruptedException e) {
throw new IllegalStateException("It should never happen while sleeping.", e);
}
}
}
Sendo que esse componente é usado normalmente pelo controller:
@RestController
@Slf4j
public class ServiceAController {
// ...
@Autowired
private Sleeper sleeper;
@GetMapping("/albums/random")
public Album getRandomAlbum() {
// ...
sleeper.sleepWithCustomSpan();
// ...
}
}
Temos então como resultado a visualização do span “sleepingCustomSpan” (inclusive com seu tempo de duração) no trace:
Sobre o uso da anotação @WithSpan, um alerta: essa anotação funciona com o framework de aspectos do Spring Boot, de tal sorte que apenas métodos “proxificados” pelo framework podem ser anotados desas forma. Ou seja, o método com @WithSpan deve ser público e invocado de outro bean (i.e., não pode ser privado ou público, mas chamado dentro da mesma classe). Caso você queira gerar um span personalizado para um trecho mais específico de código, há a opção programática, que seria algo assim (não testamos):
Span span = tracer.spanBuilder("sleepingCustomSpan").startSpan();
Thread.sleep(100);
span.end();
Encontrando um trace no Jaeger pelo trace ID
Dado um trace ID, podemos encontrar facilmente seu trace correspondente no Jaeger utilizando uma caixa de busca no topo da página.
Considerações arquiteturais sobre o Collector (preocupações com resiliência e desempenho)
Com ou sem Collector?
Por que ter um Collector? Afinal, seria possível e fácil fazer com que a aplicação (instrumentada com Otel) enviasse os dados diretamente para o Jaeger.
Pois bem. Considere a comunicação entre a aplicação e o Otel Collector. Nesse momento, o cliente (em nossa aplicação) envia dados ao servidor do Collector. O que ocorre se essa comunicação estiver lenta? Vai lerdear nossa aplicação? O que acontece se essa comunicação falhar? Eventos serão perdidos?
Bom, o cliente do Otel possui mecanismos de resiliência (basicamente envios assíncronos em lote, timeouts e reenvios). Principalmente devido a assincronicidade do envio (as threads principais da aplicação não são bloqueadas), o impacto na aplicação é amenizado (mas vamos considerar aqui que algum impacto ainda é possível). E esses mecanismos se aplicam tanto ao envio para o Collector quanto ao envio direto para um backend como o Jaeger.
Só que com o OpenTelemetry, podemos enviar os dados de telemetria não apenas para um, mas para vários backends. Digamos que vamos enviar os traces para o Jaeger e para o Grafana Tempo e também enviar os logs para o Loki. Nesse caso, os problemas de falhas na comunicação se multiplicam. Quando enviamos tudo para o Collector, pelo menos há um único canal de comunicação que pode comprometer o desempenho da aplicação. Com vários canais de comunicação, a situação tem mais chances de pioras.
E há mais uma questão de manutenibilidade. A escolha do backend não é trivial: vamos usar o Jaeger, o OpenZipkin ou o Grafana Tempo para ver os traces? Digamos que todos os serviços do sistema estão com a instrumentação do Otel conectada diretamente ao Jaeger. Se quisermos mudar nossa ferramenta de visualização para o Tempo, teremos que fazer manutenções em todos os serviços. Já com o Collector no meio do caminho, precisamos reconfigurar apenas o Collector, sem incomodar as diversas equipes de desenvolvimento que mantêm os diferentes serviços.
Collector remoto vs Collector local
E há mais um ponto a se considerar sobre o Collector: ele pode rodar colocado (como um sidecar) ao serviço. Isso é muito interessante do ponto de vista da resiliência, pois garantimos uma comunicação extremamente eficiente entre o serviço e o Collector, liberando logo a conexão do serviço e evitando que problemas de rede dessa comunicação afetem o serviço. Depois, se o Collector tiver problemas para enviar os dados para o backend, isso pode afetar menos a operação do serviço instrumentado.
Contudo, se consideramor que os recursos de rede ainda são compartilhados (entre aplicação e Collector local) e que o cliente Otel já possui envio assíncrono não-bloqueante, então talvez o ganho com resiliência trazido pelo Collector local seja mínimo.
E há ainda outros fatores que jogam contra o Collector local. Se o pod do serviço cair (acontece), perdas de dados de telemetria podem ocorrer. Mas talvez essa desvantagem não seja tão significativa, pois o mesmo pode ocorrer com o Collector remoto: aplicação está tendo problemas para enviar dados ao Collector e antes que ela consiga fazer o reenvio, o pod morre e dados são perdidos.
A maior desvantagem do Colector em localhost fica sendo então, dependendo do contexto, a viabilidade de sua implantação colocada ao serviço. Em alguns contextos, desenvolvedores não terão autonomia para tal e precisarão de uma boa parceria com a área de infraestrutura. Em um contexto de nuvem, em que pods morrem o tempo todo, é preciso garantir que a implantação do Collector em localhost seja automatizada junto com a criação do pod que hospeda o serviço. Uma outra possível dificuldade é a atualização da configuração do Collector se necessário. Assim é preciso avaliar cada situação concreta.
Conclusões
Configuramos nossos serviços Spring Boot para trabalharem com a instrumentação do OpenTelemetry enviando dados para o Otel Collector, que por sua vez repassa esses dados ao Jaeger. Dessa forma, conseguimos visualizar nossos rastros distribuídos pelo Jaeger com visibilidade de:
- invocações entre serviços na visão de trace,
- logs no contexto de seus respectivos spans na visão de trace,
- erros e stack traces na visão de trace,
- spans personalizados na visão de trace,
- consultas SQLs executadas na visão de trace,
- trace ID nos registros de log e
- trace ID nas mensagens de erro interno.
Por fim, traçamos algumas considerações sobre escolhas arquiteturais envolvendo o uso do OpenTelemetry Collector. Concluímos que o uso do Collector traz vantagens. Contudo, o uso do Collector local tipicamente traz desafios que não compensam algum eventual benefício marginal na questão de resiliência quando comparado ao Collector remoto.