Relação de Logs e Traces

Quando você instrumenta uma aplicação com OpenTelemetry, o contexto do trace (trace context) é automaticamente propagado através da aplicação. Isso significa que você tem uma "linha do tempo" das operações que acontecem.

• Cada requisição gera um trace que possui um identificado único.
• Quando um log é gerado, eles podem ser automaticamente correlacionados com o trace através desse identificador

A beleza desse sistema é que quando você precisa debugar um problema, pode ver:

• O fluxo completo da requisição (trace)
• Todos os logs relacionados àquela execução específica
• As métricas associadas

É como ter uma "história completa" de cada requisição, onde você pode ver não só o caminho que ela percorreu, mas também todos os detalhes do que aconteceu em cada etapa.

No projeto se quiser ver essa alteração estará na branch logs.

Em todo-service.ts temos isso.

app.get('/todos', async (req, res) => {
    requestCounter.add(1);
    const user = await axios.get('http://auth:8080/auth');
    const todoKeys = await redis.keys('todo:*');
    const todos: any[] = [];

    for (const key of todoKeys) {
        const todoItem = await redis.get(key);
        if (todoItem) {
            todos.push(JSON.parse(todoItem));
        }
    }

    if(req.query['slow']){
        await sleep(1000);
    }

    if(req.query['fail']){ // Vamos falar desse if
        // E aqui estamos logando um erro caso passamos ?fail=1
        await console.error('Really Bad error!');
        res.sendStatus(500);
    }

    res.json({ todos, user: user.data });
});

Esse log esta indo para o console, mas seria muito bom se pudessemos logar usando no contexto do trace.

Vamos mudar aquele if para isso aqui.

//Vamos usar a skd do opentelemetry
import { api } from '@opentelemetry/sdk-node';
// Código...

app.get('/todos', async (req, res) => {
    // Código...

    if(req.query['fail']){
        try{
            // Simulação de um erro - lança uma exceção propositalmente
            throw new Error('Really Bad error!')
        } catch (e: any) {
            // Obtém o span (intervalor) atual do contexto de trace
            const activeSpan = api.trace.getSpan(api.context.active());
            // Registra a exceção no span atual, permitindo que ela apareça no trace
            // Se activeSpan existir, então chama o método recordException
            activeSpan?.recordException(e) // Esse é a linha que nos interessa
            // Loga o erro junto com informações importantes do trace no console para podermos ver.
            console.error('Really Bad error!', {
                spanId: activeSpan?.spanContext()?.spanId,,     // ID único deste span específico
                traceId: activeSpan?.spanContext()?.traceId,   // ID único da transação inteira
                traceFlag: activeSpan?.spanContext()?.traceFlags, // Flags do trace (ex: amostragem)
            });
            // Retorna status 500 (erro interno do servidor)
            res.sendStatus(500);
            return
        }
        // Código...
    }
});
// Código...

Fazendo a requisição e conferindo o que temos.

curl http://localhost:8081/todos?fail=1

Lá no log do compose temos esse log no console mostrando nosso spanId, traceId e traceFlag

todo-1        | Todo service is running on port 8080
todo-1        | prometheus scrape endpoint: http://localhost:9464/metrics
todo-1        | Really Bad error! {
todo-1        |   spanId: '7f830392097970ee',
todo-1        |   traceId: '66c8f22097c5adf08452acea0e8cf23a',
todo-1        |   traceFlag: 1
todo-1        | }

Você pode (e muitas vezes é recomendado) adicionar logs em vários pontos do trace, não apenas em exceções como fizemos acima.

Você pode usar o span para registrar eventos importantes durante toda a execução do código. Alguns exemplos abaixo.

Logs de eventos normais

activeSpan?.addEvent('Iniciando busca no banco');
activeSpan?.addEvent('Dados encontrados', { attributes: { count: 5 } });

Logs de exceções (como fizemos acima)

activeSpan?.recordException(error);

Logs de estado/progresso

activeSpan?.addEvent('Cache hit');
activeSpan?.addEvent('Processamento 50% completo');

Logs com contexto de negócio

activeSpan?.addEvent('Pedido processado', {
    attributes: {
        orderId: '123',
        status: 'approved'
    }
});

A ideia é que você pode usar logs para contar a "história" completa da execução, não apenas quando algo dá errado. Isso ajuda muito no debugging e na compreensão do comportamento do sistema em produção.

É nesse momento que mudamos a forma que usamos os logs em aplicações distribuídas.

É necessário fazer isso manualmente? Não. Se a biblioteca para gravar logs tiver uma instrumentação para o opentelemetry isso será feito automaticamente. No caso do NodeJS, nosso projeto exemplo, temos uma chamada Winston que é bem popular, flexível e com transporte de vários formatos. Mas ainda temos outras como Pino, Bunyan, Morgan, etc, cada um com foco e melhor para coisas diferentes.

Se não quiser usar uma biblioteca, basta criar uma função de log e apenas usá-la.