Todo mundo que trabalha com backend há algum tempo já esteve nessa situação: você tem um microserviço que chama outro que, por sua vez, chama outro, que chama outros dois, e cada um chama mais dois ou três e, no meio dessa salada toda:

Request failed with status 500 (A requisição falhou com status 500)

Como assim? Que request? Por que erro 500? Qual microserviço falhou? Qual foi o erro? Foi banco fora do ar? Foram dados incorretos na request? Foi erro no código? Será que eu esqueci de passar algum parâmetro? Oqq tacon teseno??

E aí, como caçar esse erro e resolver o problema?
Eu costumava sair olhando, um a um, os logs de todos os microserviços, pra saber onde tinha acontecido o erro; o que, geralmente, funcionava, exceto pelo fato de que, muitas vezes, um log de erro desses é, mais ou menos, assim:

Promise { <pending> }
Error: getaddrinfo ENOTFOUND fluvers
    at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:60:26) {
  errno: -3008,
  code: 'ENOTFOUND',
  syscall: 'getaddrinfo',
  hostname: 'fluvers',
  config: {
    // Um monte de campos que ocupam espaço e não te dizem nada
  },
  response: undefined,
  isAxiosError: true,
  toJSON: [Function (anonymous)]
}

O que é até OK de ler, mas que, quando jogados no meio de outros trocentos logs, em trocentas instâncias de trocentos pods no kubernetes, vira um verdadeiro inferno pra achar e entender.

Mas e aí, meu bom, como que resolve?

Entra no palco o Distributed Tracing

Distributed Tracing

Definição

Segundo a OpenTracing, Distributed Tracing (aqui chamado de Rastreamento Distribuído) é “um método utilizado para traçar perfis e monitorar aplicações, especialmente aquelas construídas utilizando uma arquitetura de microserviços. Distributed tracing ajuda a apontar onde falhas ocorreram e o que causa performance degradada”

Basicamente, consiste em armazenar o log de todas as suas requisições e operações em uma API separada, pra que isso possa ser consultado posteriormente

OpenTracing

O OpenTracing é um projeto que visa documentar e criar padrões para realização de rastreamento distribuído. Ele é composto por:

• A especificação de uma API que possibilita o rastreamento
• Bibliotecas e frameworks que implementaram essa especificação
• Documentação do projeto

O principal conceito que precisamos para esse artigo é o de span: ele representa um espaço de tempo no qual uma operação ocorreu. Outro conceito importante é o de trace, que é, de forma rasa, um conjunto de spans relacionados um com o outro.

Para saber mais sobre os conceitos específicos do OpenTracing, consulte a documentação oficial

Mais recentemente, os projetos OpenTracing e OpenCensus se juntaram e formaram o projeto Open Telemetry, nome que vou usar pra falar do projeto daqui pra frente.

Implementação

Chega de lero-lero, bora pro código!

Para podermos realizar o rastreamento automático das nossas requisições em node, vamos utilizar quatro das bibliotecas abertas disponibilizadas pelo Open Telemetry:

• @opentelemetry/node
• @opentelemetry/core
• @opentelemetry/tracing
• @opentelemetry/exporter-jaeger

Vamos utilizar, também, o Jaeger para armazenar e visualizar nossos logs.

Para isso, vamos primeiro implementar dois serviços simples com express em NodeJS: service-1 e service-2. O primeiro serviço chama o segundo que, por sua vez, chama uma API externa; vamos usar o serviço JSON Placeholder como exemplo.

Estrutura de pastas

Comece criando a estrutura de pastas que vamos precisar; no meu caso, chamei a pasta raiz do projeto de hello-jaeger. Dentro dela, criei uma pasta para cada serviço, sendo, então, service-1 e service-2.

A estrutura final deve ser algo como:

hello-jaeger
├── service-1
└── service-2

Código inicial

Para cada serviço, crie também um package.json e um index.js.

Para o service-1:

// service-1/package.json
{
  "name": "service-1",
  "version": "1.0.0",
  "description": "Simple service to learn jeager",
  "main": "index.js",
  "scripts": {
    "start": "node index.js"
  },
  "dependencies": {
    "@opentelemetry/core": "^0.3.2",
    "@opentelemetry/exporter-jaeger": "^0.3.2",
    "@opentelemetry/node": "^0.3.2",
    "@opentelemetry/plugin-http": "^0.3.2",
    "@opentelemetry/tracing": "^0.3.2",
    "axios": "^0.19.1",
    "express": "^4.17.1"
  }
}

// service-1/index.js
const axios = require('axios')
const express = require('express')

const SERVICE_2_URL = 'http://localhost:3001'

const service2 = axios.create({ baseURL: SERVICE_2_URL })

const app = express()

app.post('/posts', async (req, res) => {
  const payload = req.body

  const response = await service2.post('/posts', payload)

  res.status(response.status)
    .json(response.data)
})

app.listen(3000, () => { console.log('Service 1 ouvindo na porta 3000') })

E, para o service-2:

// service-2/package.json
{
  "name": "service-2",
  "version": "1.0.0",
  "description": "SImple service to learn jeager",
  "main": "index.js",
  "scripts": {
    "start": "node index.js"
  },
  "dependencies": {
    "@opentelemetry/core": "^0.3.2",
    "@opentelemetry/exporter-jaeger": "^0.3.2",
    "@opentelemetry/node": "^0.3.2",
    "@opentelemetry/plugin-http": "^0.3.2",
    "@opentelemetry/tracing": "^0.3.2",
    "axios": "^0.19.1",
    "express": "^4.17.1"
  }
}

// service-2/index.js
const axios = require('axios')
const express = require('express')

const app = express()

app.post('/posts', async (req, res) => {
  const post = req.body

  const response = await axios.post('https://jsonplaceholder.typicode.com/posts', post)

  res.status(response.status)
    .json(response.data)
})

app.listen(3001, () => { console.log('Service 2 ouvindo na porta 3001') })

Por último, precisamos instalar as dependências dos nossos dois serviços. Fazemos isso utilizando npm i na pasta de cada serviço.

Nesse ponto, se executarmos nosso index.js da raiz de cada serviço, o resultado será esse:

E, se enviarmos um POST /posts para nosso service-1, que está ouvindo na porta 3000, teremos o seguinte resultado:

Show! Nossos serviços estão funcionando e se comunicando! Vamos pro próximo passo.

Adicionando o rastreamento

Como dito anteriormente, vamos utilizar as bibliotecas disponibilizadas pelo projeto OpenTelemetry para fazer o rastreamento das nossas requisições. Os arquivos package.json que criamos na seção anterior já declaram a dependência desses pacotes, então não precisamos instalá-los agora.

O primeiro passo é muito simples: importamos as bibliotecas de rastreamento e as inicializamos em cada microserviço, antes de chamar o express (require('express')).

Vamos realizar essa inicialização no ponto de entrada de cada microserviço; no nosso caso, esse ponto de entrada é o arquivo index.js. Para isso, vamos acrescentar as seguintes linhas, no começo do arquivo:

// index.js
const { NodeTracer } = require('@opentelemetry/node')
const { initGlobalTracer } = require('@opentelemetry/core')
const { SimpleSpanProcessor } = require('@opentelemetry/tracing')
const { JaegerExporter } = require('@opentelemetry/exporter-jaeger')

const tracer = new NodeTracer({ // 1.
  plugins: {
      http: {
        enabled: true,
        path: '@opentelemetry/plugin-http' // 2.
      }
  },
})

const exporter = new JaegerExporter({ // 3.
  serviceName: 'service-1', // Nome do serviço que vai aparecer no log mais tarde
  host: 'localhost' // Endereço da API do Jaeger
})

tracer.addSpanProcessor(new SimpleSpanProcessor(exporter)) // 4.

initGlobalTracer(tracer) // 5.

Explicando os pontos do código:

1. O NodeTracer é responsável por interceptar as chamadas à função require do node e injetar, nos módulos que são carregados através do require, o código responsável por fazer o rastreamento da requisição. Ele, por si só, não modifica nenhum módulo; a injeção do código por si só fica a cargo dos plugins, como o que vamos ver abaixo.
2. Plugin responsável por adicionar o código de rastreamento às chamadas da biblioteca http do Node, que o express utiliza para criar o servidor HTTP que ele sobe para atender às requisições.
3. O exporter é responsável por obter os dados dos nossos spans e enviá-los à API do Jaeger
4. O SpanProcessor é responsável por processar nossos spans; nesse caso, ele utiliza o exporter do Jaeger para realizar esse processamento
5. Por último, dizemos à biblioteca de rastreamento que queremos utilizar nosso NodeTracer para realizar o rastreamento de todos os spans que acontecerem no processo todo.

Antes de executarmos o código, precisamos subir a API do Jaeger, responsável por armazenar nossos spans. Pra facilitar, vamos utilizar a imagem do Docker que o Jaeger disponibiliza chamada All-In-One, com o seguinte comando no terminal:

$ docker run -d --name jaeger \
  -e COLLECTOR_ZIPKIN_HTTP_PORT=9411 \
  -p 5775:5775/udp \
  -p 6831:6831/udp \
  -p 6832:6832/udp \
  -p 5778:5778 \
  -p 16686:16686 \
  -p 14268:14268 \
  -p 9411:9411 \
  jaegertracing/all-in-one:1.16

Essa imagem é responsável por subir todos os componentes de tracing do Jaeger de uma vez; vale lembrar, no entanto que a imagem all-in-one salva todos os rastreamentos em memória, o que faz com que eles se percam caso o container seja reiniciado; sendo assim, seu uso em produção não é recomendado, devendo-se utilizar de outros métodos par disponibilização do serviços do Jaeger. No entanto, para fins de teste e em ambiente de desenvolvimento, essa imagem nos atende bem. Para instruções de como instalar o Jaeger em produção, consulte a documentação oficial (em inglês)

Agora, vamos executar nossos microserviços e enviar nossas requisições novamente. O resultado no terminal agora deverá incluir algumas linhas de logs vindos das bibliotecas se comunicando com a API do Jaeger.

A mágica começa quando abrimos o endereço http://localhost:16686/ no navegador, selecionamos "service-1" no campo "Service" e clicamos em "Find Traces":

Ao clicar no resultado encontrado, podemos ver todos os spans que aconteceram dentro da requisição para /posts:

É lindo!

Adicionando mais informações

Apesar de já ser muito útil, saber o status de cada request e o que aconteceu durante ela, muitas vezes, não é o bastante. Felizmente, existe uma forma de customizar o span e adicionar mais informações a ele. Vamos, então, adicionar um middleware que salve, além das informações que já temos, o conteúdo da requisição e da resposta ao span; esse mesmo middleware também adicionará o ID do trace a um header chamado Jaeger-Trace-Id no resposta.

É bem simples; basta adicionarmos o seguinte código antes do nosso endpoint de POST /posts do express:

const mung = require('express-mung')
const opentelemetry = require('@opentelemetry/core')

// Restante do código, incializando o tracer e a aplicação

app.use(mung.json((body, req, res) => {
  const tracer = opentelemetry.getTracer()
  const span = tracer.getCurrentSpan()

  if (!span) return

  const { traceId } = span.context()

  span.addEvent('', { request: JSON.stringify({ body: req.body }, null, 4) })
  span.addEvent('', { response: JSON.stringify({ body }, null, 4) })

  res.append('Jaeger-Trace-Id', traceId)
}))

Depois de adicionar o código no index.js dos dois serviços, precisamos instalar o express-mung, responsável por coletar os dados da resposta e chamar uma função que passamos quando esses dados estiverem disponíveis. Fazemos isso com o comando:

npm i express-mung

Uma vez que tudo está instalado, podemos, de novo, executar nossos services, enviar nossa requisição, e, na interface do Jaeger, clicar novamente em "Find Traces". Dessa vez, um segundo trace deve aparecer. Clicando nele, temos o seguinte resultado:

Clicando em "Logs", podemos ver que, dessa vez, os dados inclusos na nossa requisição foram armazenados juntamente com ela:

Uma situação interessante que eu resolvi retratar aqui pra mostrar o quanto o rastreamento das requisições pode salvar nossas vidas: olhando para o body da request, vemos que o mesmo está vazio, mesmo que tenhamos enviado três campos mais cedo, na requisição. Isso acontece por que não adicionamos o middleware de interpretação de JSON do express, o bodyParser. Pra fazer isso, basta instalar o módulo com npm i body-parser e adicionar o seguinte código aos serviços, antes de quaisquer middlewares ou rotas em nossos serviços:

const bodyParser = require('body-parser')

// Restante do código

app.use(bodyParser.json()) // Adicione logo após a criação do app em `const app = express()`

Pronto, se enviarmos nossa requisição novamente, e abrirmos ela na UI do Jaeger, teremos o seguinte:

Além disso, nossa requisição agora nos retornou um header chamado Jaeger-Trace-Id, contendo algo como 473e61886d05f77cb1ed9a706fba5656. Esse ID pode ser utilizado na barra de pesquisa superior da interface do Jaeger para acessar o trace diretamente.

Tornando as coisas mais fáceis (momento Jabá)

Configurar manualmente todos os middlewares e bibliotecas necessários para que todos os nossos serviços funcionem da forma que precisamos. Foi pensando nisso que o expresso foi criado.

Trata-se de uma biblioteca composta por vários módulos que são independentes, mas que se integram muito bem. Recentemente, um módulo de tracing foi adicionado ao expresso. Vale a pena conferir as documentações dos módulos e utilizar os que façam sentido pa você.

Conclusão

Trabalhar com microserviços não é, na maioria das vezes, a coisa mais fácil do mundo, e entender o que acontece entre um microserviço e outro pode ser bem complicado.

Felizmente, o Distributed Tracing nos permite saber, de forma mais fácil, exatamente o que está acontecendo nas nossas aplicações.

O conteúdo completo dos arquivos mostrados nesse artigo se encontra neste repositório. Sinta-se à vontade para perguntar, comentar e criticar.