Minimizando os problemas de produção com o rastreamento de logs

Vamos contextualizar:

Ocorreu um incidente crítico na produção. Cabe a você descobri-lo e resolvê-lo. Você investiga os logs das centenas de serviços diferentes e fica totalmente perdido. Qual ação causou qual reação? O erro está relacionado a essa chamada de API ou a essa outra? Todos nós já passamos por isso. E todos concordamos unanimemente que não é nada divertido.

Mas há uma uma solução. Uma solução que não resolverá todos os seus problemas de produção, mas que ajudará imensamente. E a boa notícia é que ela pode ser facilmente integrada aos seus serviços.

Rastreamento de logs.

Parece simples, não é? Mas, na verdade, pode ser uma ferramenta poderosa para praticamente qualquer tipo de investigação. Isso porque, nas arquiteturas modernas de hoje, quando um usuário clica em um único botão em nosso site, isso aciona uma solicitação de API para o gateway de API, para um serviço de negócios, para um banco de dados, para outro serviço, para um barramento de mensagens centralizado, para outro serviço e assim por diante.

É uma jornada avassaladora, inundada por centenas de registros gerados a cada fluxo que ocorre centenas de vezes por segundo, por centenas de milhares de usuários. Ufa.

O que você quer dizer com “rastreamento de logs”?

Antes de começarmos a implementar esses Concepts, vamos entender o que queremos dizer quando falamos em rastrear logs. Rastreamento geralmente significa adicionar algum identificador que possa ser usado para agregar dados. O significado de cada ID é, então, uma questão de preferência. Podemos ter um único ID de rastreamento que seja adicionado a todos os dados de uma única solicitação. Ou podemos ter um conjunto de IDs de span que serão usados no contexto de um serviço. A ideia básica é a seguinte:

basic log tracing flow

Há dois conceitos fundamentais a serem compreendidos:

1. Agregar todos os logs de todos os serviços para cada solicitação por meio do rastreamento

2. Deixe que a infraestrutura cuide do rastreamento, para que isso não interfira na lógica de negócios

Então, como fazemos para implementar isso?

Agrupar registros para cada solicitação

Esse conceito é bem simples. Precisamos seguir duas regras muito simples:

• Adicione o ID de rastreamento a cada registro de log que criarmos para uma solicitação e passe o ID de rastreamento sempre que realizarmos qualquer operação de E/S.

• Se dois serviços se comunicarem sobre a mesma solicitação por meio de um barramento de mensagens, adicionaremos o ID de rastreamento à mensagem enviada ao barramento. Se dois serviços se comunicarem por meio de solicitações HTTP, adicionaremos o ID de rastreamento aos cabeçalhos da solicitação. Dessa forma, podemos acompanhar uma única solicitação ao longo de todo o seu fluxo, sem qualquer interferência de outras solicitações ou registros que ocorram paralelamente.

Separação entre lógica de negócios e infraestrutura

Garantir que possamos acompanhar o rastreamento em todos os dados enviados ou recebidos pode exigir uma boa quantidade de código. Sempre buscamos separar conceitos de infraestrutura como esse da lógica de negócios, tanto quanto possível. Felizmente, no nosso caso, é fácil separar o gerenciamento do rastreamento quase que totalmente.

Em nosso código, registramos logs para diversos eventos e erros ao adicionar dados a esses logs. Queremos manter esses fluxos inalterados enquanto adicionamos nosso rastreamento a todos os logs paralelamente. A maioria das ferramentas que usamos hoje nos permite adicionar interceptadores a cada solicitação que recebem. Se nos certificarmos de adicionar interceptadores à nossa ferramenta de E/S e à nossa ferramenta de registro de logs, estaremos no caminho certo para garantir que todos os registros sejam rastreados sem alterar nenhum código existente.

A maneira mais fácil de explicar é mostrando um exemplo concreto de nossos próprios serviços.

O código abaixo pertence ao serviço Node.js que recebe solicitações HTTP, grava vários registros e, em seguida, faz uma solicitação HTTP para o próximo serviço. É um dos três pontos em que colocamos interceptadores: solicitação recebida, registro e solicitação enviada.

function tracingMiddleware(req,res,next) {
    ns.run(() => {
        let traceId = req.headers['x-b3-traceid'];
        let spanId = req.headers['x-b3-spanid'];
        if (!traceId || !spanId) {
            traceId = uuid().replace(/-/g, '');
            spanId = uuid().replace(/-/g, '').substring(16);
        }
        ns.set('traceId', traceId);
        ns.set('spanId', spanId);
        next();
    });
}

Utilizamos o Express como nossa infraestrutura de API para implementar middlewares do Express middlewares que interceptam cada solicitação. Extraímos o ID de rastreamento da solicitação ou criamos um novo, caso sejamos o primeiro serviço da cadeia. Em seguida, armazenamos o ID de rastreamento em uma ferramenta de armazenamento de sessão para que possamos recuperá-lo em cada etapa do processo.

Observe o ns.set. Isso está usando cls-hooked, um pacote de armazenamento local de continuação que encapsula os hooks assíncronos do Node. Isso nos permite armazenar localmente o ID de rastreamento de cada sessão. Mas, se você estiver usando o Node 14, essa funcionalidade já vem integrada com armazenamento local assíncrono. O que é legal nesse método, porém, é que ele pode ser implementado em qualquer linguagem.

Em seguida, adicionamos um interceptador à ferramenta de registro de logs que obtém o ID de rastreamento do armazenamento de sessão e o acrescenta a cada linha de log:

function createBunyanStreamMiddleware(streams) {
    return {
        type: 'raw',
        level: process.env.LOG_LEVEL,
        stream: {
            write: (entry) => {
                if(ns && ns.active) {
                    entry['traceId'] = ns.get('traceId');
                    entry['spanId'] = ns.get('spanId');
                }
                streams.forEach((stream) => {
                        stream.stream.write(entry)
                });
            }
        }
    }
}

Por fim, adicionamos um interceptador à ferramenta HTTP que insere o ID de rastreamento nos cabeçalhos da solicitação antes que ela seja enviada:

function insertTracingHeaders(config = {}){
    if(ns && ns.active) {
        const traceId = ns.get('traceId');
        const spanId = ns.get('spanId');
        if (!config.headers) {
            config.headers = {};
        }
        if (traceId && spanId) {
            config.headers['x-b3-parentspanid'] = spanId;
            config.headers['x-b3-traceid'] = traceId;
        }
    }
    return config;
}

Todo o fluxo ficará mais ou menos assim:

tracing flow with interceptors

Conclusão

O rastreamento de logs pode ser usado em diversos contextos, mas esse uso específico evita muitas dores de cabeça na investigação de erros. Ele garante que os logs de solicitação de cada fluxo fiquem facilmente acessíveis, de modo que você não precise vasculhar milhares de logs não relacionados.

Podemos afirmar, por experiência própria, que nos serviços em que aplicamos esses Concepts, a eficiência e o valor agregados durante a análise de logs dispararam. Desde então, analisar logs de qualquer outra forma simplesmente não parece mais a coisa certa a se fazer.

Então, da próxima vez que ocorrer um incidente crítico na produção e couber a você resolvê-lo, pelo menos dessa vez os registros estarão do seu lado.