Distributed tracing com Jaeger em NodeJS: Descubra com quem seus microserviços andam conversando
Tags: node, javascript, tracing, tutorial
Published: 2020-01-19 05:32:58

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:

```javascript
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.

<big>Mas e aí, meu bom, **como que resolve?**</big>

<big>*Entra no palco o Distributed Tracing*</big>

## Distributed Tracing

### Definição

Segundo a [OpenTracing](https://opentracing.io/docs/overview/what-is-tracing), **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](https://opentracing.io/docs/overview)

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](https://npmjs.com/package/@opentelemetry/node)
- [@opentelemetry/core](https://npmjs.com/package/@opentelemetry/core)
- [@opentelemetry/tracing](https://npmjs.com/package/@opentelemetry/tracing)
- [@opentelemetry/exporter-jaeger](https://npmjs.com/package/@opentelemetry/exporter-jaeger)

Vamos utilizar, também, o [Jaeger](https://www.jaegertracing.io) 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](https://jsonplaceholder.typicode.com) 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`:

```json
// 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"
  }
}
```

```javascript
// 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`:

```json
// 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"
  }
}
```

```javascript
// 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:

![captura de tela do terminal, com o comando "node service-1/index.js" inserido e mostrando "Service 1 ouvindo na porta 3000" como resultado](https://thepracticaldev.s3.amazonaws.com/i/qume72ghhkubzrm1gbzc.png)

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

![imagem do terminal, mostrando um comando para realizar uma requisição POST, e o resultado, que é um JSON com um campo "id" e valor 101](https://thepracticaldev.s3.amazonaws.com/i/vh6lvserlwd1s1ijaijy.png)

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:

```javascript
// 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](https://docker.com) que o Jaeger disponibiliza chamada [All-In-One](https://www.jaegertracing.io/docs/1.16/getting-started/#all-in-one), com o seguinte comando no terminal:

```sh
$ 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)](https://www.jaegertracing.io/docs/1.16/deployment/)

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":

![imagem da tela do Jaeger, mostrando um resultado encontrado sendo uma requisição para /posts](https://thepracticaldev.s3.amazonaws.com/i/jp6zmhzkc2b8m879ycr3.png)

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

![imagem do tracing no Jaeger mostrando três operações: uma principal e duas segundárias](https://thepracticaldev.s3.amazonaws.com/i/6ilijc8dngm5jb78i4sx.png)

É **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:

```javascript
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:

```sh
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:

![captura da tela do Jaeger, dessa vez mostrando três spans, dois deles com uma propriedade "Logs"](https://thepracticaldev.s3.amazonaws.com/i/cwij0yzcqkfwju6sdpzq.png)

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

![captura de tela do Jaeger mostrando que mais informações foram adicionadas ao span](https://thepracticaldev.s3.amazonaws.com/i/x4f4scugnso6ja325s3s.png)

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:

```javascript
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:

![captura de tela da interface do Jaeger mostrando uma requisição com os dados de requisição e de resposta](https://thepracticaldev.s3.amazonaws.com/i/y8ch8xuhf6p33ugl6hn8.png)

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](https://github.com/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](https://github.com/expresso/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](http://github.com/rjmunhoz/hello-jaeger) repositório. Sinta-se à vontade para perguntar, comentar e criticar.