Structured Logging em Node.js: Como um ID de Negócio Virou Meu correlationId

Trabalho com software há mais de 15 anos. Esse é o primeiro texto que resolvo escrever sobre o trabalho. Escolhi esse tema porque foi um problema pequeno, real, que me custou tempo mais de uma vez até eu parar e resolver direito.

Vale um adendo rápido: isso aqui não é tracing distribuído nem observabilidade para múltiplos serviços. É uma solução pontual para um problema específico: correlacionar logs dentro da execução de um Step Function. Se o seu cenário for outro, o problema muda de forma. O que importa aqui é o raciocínio, não a receita.

Contexto rápido pra quem não trabalha com serverless: o AWS Step Functions é um serviço de orquestração. Você desenha um workflow como uma máquina de estados (JSON), e cada estado geralmente aciona uma AWS Lambda (uma função que roda sob demanda, sem servidor pra gerenciar). No meu caso, um pedido dispara uma execução da state machine, que vai passando por várias Lambdas em sequência: algumas fazem validação, outras chamam serviços externos, uma espera resposta de um callback antes de continuar.

A solução acabou sendo mais simples do que parece: um campo que o Step Functions já oferecia de graça, e que eu simplesmente não estava usando.

Um pedido foi processado há 120 dias. O cliente liga: “Vocês receberam minha solicitação? Nunca tive retorno.”

Você abre o AWS Console. A execução do Step Functions já sumiu. O histórico de execução só fica disponível por 90 dias, e mesmo dentro desse prazo, achar uma execução específica em meio a milhares já é complicado. Sobra o CloudWatch, com os logs de cada Lambda do pipeline.

Você tem um dado: o ID do caso. Mas cada Lambda logava do seu jeito: sem padrão, sem correlação entre elas. Para reconstruir o que aconteceu, você precisa abrir os logs de cada função na ordem em que o workflow provavelmente executou, e juntar os pedaços na mão.

Não era o erro em si que doía. Era o tempo perdido só para organizar os logs antes de começar a investigar de verdade.

O Caos

O pipeline não era gigante, mas também não era trivial: alguns steps de decisão com bifurcações (dependendo do tipo de fluxo, o caminho mudava) e uma etapa de callback (uma Lambda que esperava resposta externa antes de continuar).

Cada Lambda logava separado, com console.log() espalhado pelo código. O identificador mínimo (o ID do caso) até aparecia em alguns logs, mas sem padrão nenhum entre as funções. Uma Lambda logava um texto solto, outra logava um objeto, nenhuma seguia o mesmo formato.

O resultado: nenhuma correlação real. Para reconstruir o que tinha acontecido, você tinha que pensar na ordem provável de execução do workflow e ir abrindo os log groups um por um, tentando montar a linha do tempo na mão.

E o problema da retenção curta tornava tudo pior: sem o histórico da execução, restavam só os logs crus do CloudWatch, e como eles não tinham nenhuma estrutura em comum, não dava para usar um para compensar a ausência do outro. Faltava exatamente o elo que faria os dois se completarem.

A Virada

Uma opção seria gerar um correlationId novo (um UUID) no início de cada execução, e propagar ele manualmente por todas as Lambdas. É a solução mais óbvia, e funciona. Mas no meu caso não fazia sentido: eu já tinha o ID do caso, que identificava a execução do início ao fim. Criar um segundo ID só pra correlacionar logs significava manter dois identificadores pra mesma coisa, e toda investigação viraria uma tradução: primeiro acha o ID do caso, depois descobre o correlationId associado, só então busca nos logs.

Não foi uma sacada complexa. O AWS Step Functions já permite nomear cada execução (name) no momento em que ela é iniciada, e esse nome fica disponível em todos os estados do workflow através da variável de contexto $$.Execution.Name, sem precisar passar nada manualmente entre etapas. Bastava usar o que já existia: em vez de gerar um UUID aleatório como nome da execução, usei o próprio ID do caso:

const input: StartExecutionCommandInput = {
  stateMachineArn: getStateMachineArn(),
  name: data.id, // o ID do caso vira o nome da execução
  input: JSON.stringify(data),
};

Enter fullscreen mode Exit fullscreen mode

A partir daí, qualquer estado da state machine consegue acessar esse ID sem esforço:

"Parameters": {
  "data.$": "$",
  "correlationId.$": "$$.Execution.Name"
}

Enter fullscreen mode Exit fullscreen mode

Um único identificador, do início ao fim: o mesmo ID do caso que aparece no banco de dados é o que aparece nos logs de todas as Lambdas do pipeline. Sem UUID extra, sem tabela de mapeamento, sem tradução.

A Implementação

A solução tem algumas peças que se encaixam.

1) O Logger: estruturado, com contexto por camada

O core é uma função createLogger(layer, category) que retorna um logger já “pré-configurado”, sabendo de onde ele está sendo chamado. Isso elimina a repetição de campos manuais em cada log:

export type LogLevel = 'info' | 'warn' | 'error';
export type LogLayer = 'handler' | 'service' | 'wrapper' | 'authorizer' | 'util';

export interface LogEntry {
  message: string;
  eventCode: string;
  category: string;
  layer: LogLayer;
  correlationId?: string;
  [key: string]: unknown;
}

const REDACTED_KEYS = ['token', 'authorization', 'password', 'secret', 'apikey', 'x-api-key'];
const REDACTED_VALUE = '[REDACTED]';

export const redact = (value: unknown): unknown => {
  if (Array.isArray(value)) return value.map(redact);

  if (value !== null && typeof value === 'object') {
    return Object.entries(value as Record<string, unknown>).reduce<Record<string, unknown>>(
      (acc, [key, nestedValue]) => {
        const shouldRedact = REDACTED_KEYS.some((k) => key.toLowerCase().includes(k));
        acc[key] = shouldRedact ? REDACTED_VALUE : redact(nestedValue);
        return acc;
      },
      {},
    );
  }

  return value;
};

const writeLog = (level: LogLevel, entry: LogEntry): void => {
  const redacted = redact(entry) as Record<string, unknown>;
  console[level === 'warn' ? 'warn' : level === 'error' ? 'error' : 'info'](redacted);
};

export const createLogger = (layer: LogLayer, category: string) => ({
  info: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('info', { ...entry, layer, category }),
  warn: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('warn', { ...entry, layer, category }),
  error: (entry: Omit<LogEntry, 'layer' | 'category'>) =>
    writeLog('error', { ...entry, layer, category }),
});

Enter fullscreen mode Exit fullscreen mode

Três detalhes que valem destacar:

• Redação automática: qualquer campo com nome parecido a token, password, secret etc. é substituído antes de sair para o console, sem depender de disciplina manual em cada log.
• layer + category: todo log já nasce sabendo de onde veio (handler, service, wrapper…) sem precisar escrever isso toda vez.
• Genérico o suficiente: o entry aceita qualquer campo adicional ([key: string]: unknown), então dá pra logar praticamente qualquer objeto (request, response, resultado de uma query, payload de erro) sem precisar adaptar o logger pra cada tipo de dado. O mesmo logger serve pra handler, service, wrapper ou util. ### 2) Entrada via workflow: o wrapper de cada step

Cada estado da state machine repassa o $$.Execution.Name como correlationId para o payload da próxima Lambda:

{
  "Type": "Task",
  "Resource": "${SomeFunctionArn}",
  "Parameters": {
    "data.$": "$",
    "correlationId.$": "$$.Execution.Name"
  },
  "ResultPath": "$.someResult"
}

Enter fullscreen mode Exit fullscreen mode

Um wrapper genérico em cada Lambda do fluxo cuida do log de entrada/saída/erro automaticamente:

export function stepFunctionWrapper<TIn, TOut>(stepName: string, fn: (arg: TIn) => Promise<TOut>) {
  return async (data: TIn): Promise<TOut> => {
    const log = createLogger('wrapper', stepName);
    const correlationId = (data as { correlationId?: string })?.correlationId;

    try {
      log.info({ message: 'Starting step execution', eventCode: 'StepStarted', correlationId });
      const result = await fn(data);
      log.info({ message: 'Step execution successful', eventCode: 'StepCompleted', correlationId });
      return result;
    } catch (err) {
      log.error({ message: 'Step execution failed', eventCode: 'StepFailed', correlationId, error: String(err) });
      throw err;
    }
  };
}

Enter fullscreen mode Exit fullscreen mode

3) O logger dentro do handler

O wrapper cuida do log de “step iniciado / concluído / falhou” de forma genérica. Mas dentro da lógica de negócio, faz sentido logar pontos específicos: não só “começou e terminou”, mas também decisões e IDs que vão importar numa investigação futura.

O padrão que se repete em cada handler:

import { createLogger } from '../../../util/logger';
import { stepFunctionWrapper } from '../stepFunctionWrapper';

// Logger criado uma vez, no topo do módulo — reaproveitado em toda a função
const log = createLogger('handler', 'createRecord');

export const handler = async ({
  data: request,
  correlationId,
}: {
  data: CreateRecordRequest;
  correlationId?: string;
}): Promise<number> => {
  log.info({
    message: 'Creating record',
    eventCode: 'HandlerStarted',
    correlationId,
    externalId: request.externalId, // o ID do caso, sempre junto
  });

  // ...lógica de negócio (validações, criação, etc)

  const { id: recordId } = await models.Record.create({ /* ... */ });

  log.info({
    message: 'Record created',
    eventCode: 'HandlerSuccess',
    correlationId,
    externalId: request.externalId,
    recordId, // o ID interno também, para cruzar com o banco depois
  });

  return recordId;
};

export const createRecord = stepFunctionWrapper('createRecordHandler', handler);

Enter fullscreen mode Exit fullscreen mode

Três decisões pequenas que fazem diferença na hora de investigar:

1. log é criado uma vez, fora da função: evita recriar o logger a cada chamada e deixa claro, só de olhar o topo do arquivo, qual layer/category aquele módulo representa.
2. correlationId sempre presente, mas nunca gerado aqui: o handler só recebe e repassa; quem cria é o wrapper, nesse caso o do Step Functions. Isso evita que alguém, no meio do código, gere um novo ID por engano e quebre a correlação.
3. eventCode como um enum implícito (HandlerStarted, HandlerSuccess, HandlerError…): dá para filtrar no CloudWatch por tipo de evento sem depender do texto livre da message. O ganho principal: mesmo numa investigação de negócio (não só um erro técnico, tipo “por que esse registro ficou com status errado?”), os logs já têm os IDs certos amarrados desde a criação. Não precisa instrumentar nada na hora do incidente; já está lá.

4) Propagando o correlationId pra fora: chamadas a serviços externos

O correlationId não fica só dentro do próprio pipeline. Quando um handler chama uma API externa, o correlationId é passado como parâmetro pra função de serviço, que loga a requisição e a resposta em volta da chamada:

export const searchExternalService = async (
  request: SearchRequest,
  correlationId?: string,
  isRetry = false,
): Promise<SearchResponse> => {
  try {
    log.info({
      message: 'Requesting external service',
      eventCode: 'ServiceRequest',
      correlationId,
      requestBody: request,
    });

    const { data } = await axios.post<SearchResponse>(/* ... */);

    log.info({
      message: 'External service responded successfully',
      eventCode: 'ServiceResponse',
      correlationId,
      responseBody: data,
    });

    return data;
  } catch (error: unknown) {
    handleError(error, isRetry, correlationId);
    return searchExternalService(request, correlationId, true);
  }
};

Enter fullscreen mode Exit fullscreen mode

Não é o correlationId viajando como header pro serviço terceiro. O sistema externo não sabe da existência dele. É o request e o response daquela chamada específica ficando amarrados ao mesmo ID de correlação usado no resto do pipeline. Na prática, isso significa que, ao investigar um caso, você também vê exatamente o que foi enviado e recebido de cada integração externa, no lugar certo da timeline, e não só o que aconteceu dentro das suas próprias Lambdas.

Bônus: entrada via API (o correlationId vem de graça)

O caso central deste post é o workflow orquestrado por Step Functions, mas vale registrar: para endpoints HTTP comuns (fora do contexto de uma state machine), não é preciso gerar nada. O próprio API Gateway já fornece um requestId único por requisição, que pode assumir o mesmo papel:

export function apiWrapper<TIn, TOut>(
  handlerName: string,
  fn: (arg: TIn, event: APIGatewayProxyEvent, correlationId?: string) => Promise<TOut>,
) {
  return async (event: APIGatewayProxyEvent): Promise<APIGatewayProxyResult> => {
    const correlationId = event.requestContext?.requestId;
    const log = createLogger('wrapper', handlerName);

    log.info({ message: 'Request started', eventCode: 'HandlerStarted', correlationId });

    try {
      const inputData = event.body ? JSON.parse(event.body) as TIn : ({} as TIn);
      const result = await fn(inputData, event, correlationId);

      log.info({ message: 'Request handled successfully', eventCode: 'EndpointSuccess', correlationId });
      return { statusCode: 200, body: JSON.stringify(result) };
    } catch (err) {
      log.error({ message: 'Request failed', eventCode: 'EndpointError', correlationId, error: String(err) });
      return { statusCode: 500, body: JSON.stringify({ message: 'Internal error' }) };
    }
  };
}

Enter fullscreen mode Exit fullscreen mode

O mesmo princípio da seção anterior (usar um identificador que já existe, em vez de criar um novo) se aplica aqui também.

Resultado: Como Fica a Busca Hoje

Cliente liga de novo, mesmo cenário: “Vocês receberam minha solicitação?” Só que agora o fluxo de investigação é outro.

O ID que o cliente informa é o correlationId. Não precisa descobrir nada antes. No CloudWatch Logs Insights, agrupo todos os log groups do pipeline numa única query e filtro pela mensagem:

fields @timestamp, @message, @logStream
| filter @message like "correlationId: 'SEU-ID-AQUI'"
| sort @timestamp asc

Enter fullscreen mode Exit fullscreen mode

O resultado sai em ordem cronológica, com a jornada inteira: qual Lambda rodou, em que ordem, o que cada uma decidiu e, se algo falhou, em qual etapa exatamente e com qual erro.

O que antes levava uns bons minutos reconstruindo mentalmente a ordem de execução e abrindo log group por log group, agora vira uma única query, com o ID certo e a timeline inteira na tela.

Lições

Não teve trade-off real. Pelo contrário. Depois que o padrão ficou desenhado (logger + wrappers + convenção de eventCode), o trabalho de aplicar ficou trivial. Três coisas ajudaram a manter isso assim:

1. Documentação no README: qualquer pessoa nova no time (ou eu mesmo, 6 meses depois) sabe exatamente como logar em cada camada, sem precisar perguntar ou vasculhar código de exemplo.
2. Regra de lint proibindo console.log: a decisão de arquitetura virou uma regra automatizada. Ninguém precisa lembrar de usar o logger; o CI já rejeita quem não usar.
3. Wrappers cobrindo a parte repetitiva: stepFunctionWrapper já cuida do log de início/fim/erro de cada step, então isso não precisa ser reescrito a cada handler novo. O que ainda exige esforço deliberado é logar dentro da lógica de negócio e nas chamadas a serviços externos, mas aí o padrão já está definido, é só seguir. No fim, o padrão não sobrevive porque as pessoas lembram de segui-lo. Sobrevive porque ficou mais fácil seguir do que não seguir.