Dia 13 — Saber o que está acontecendo em produção

Informatica · Conteudo · publicado em 30/09/2026

Dia 13 de 15

Saber o que está acontecendo em produção

Aula 1

Log que responde pergunta

Procurado por log estruturado log em JSON nível de log info warn error log com contexto id da requisição correlacionar requisições log sem dado sensível token no log email no log horário no log onde o erro aconteceu

O que separa um log útil de um log jogado no arquivo

O console.log('erro aqui') não responde pergunta nenhuma. Quem lê aquilo de manhã precisa saber o que aconteceu, onde, quando e se afeta uma pessoa ou todas — e nada disso está na linha.

Um log útil responde uma pergunta concreta sem precisar abrir o servidor. A forma que resolve isso é o log estruturado: a mesma linha de sempre, com campos de nome fixo, para que a máquina possa filtrar e a pessoa possa ler.

A tabela que guarda isso tem cinco colunas, e cada uma resolve uma pergunta:

Coluna	Pergunta que responde
`dt_registro`	quando aconteceu
`st_nivel`	o quanto isso importa
`ds_request_id`	a qual requisição pertence
`ds_mensagem`	o que aconteceu
`ds_contexto`	sob que circunstância aconteceu

O dt_registro com DEFAULT CURRENT_TIMESTAMP resolve o horário no log, e é a decisão que quase todo mundo inverte: a função de log não monta data nem hora. O carimbo vem do banco, e o stdout do processo — que o gerenciador já prefixa quando captura — é a segunda fonte. Duas fontes brigando produzem um log que mente sobre quando o evento aconteceu, e a mentira aparece quando se tenta reconstruir a ordem de dois eventos.

`JSON.stringify` é o que separa a máquina da pessoa

Log em texto livre é para o olho; o log em JSON é para os dois. A linha continua legível no terminal, e grep e jq conseguem extrair campo:

const linha = { nivel, request_id: requestId, mensagem, contexto };
console.log(JSON.stringify(linha));

O ds_contexto é o campo que carrega o log com contexto: rota, método, status e o codigo_mysql quando houve erro. É ele que diz onde o erro aconteceu — "falhou ao montar relatório de itens" é uma frase; etapa: 'montar relatorio' com o SQL ao lado é a diferença entre achar e garimpar.

O mesmo JSON.stringify vai para o INSERT, gravado numa coluna JSON. A consequência prática é que dá para contar sem ler:

SELECT st_nivel, COUNT(*) AS total FROM tb_log GROUP BY st_nivel

Os níveis: o que cada um promete

O nível de log não é decoração. É a resposta para a pergunta "isso acorda alguém?".

Nível	Significado	Quem age
`error`	algo quebrou, e alguém vai ser acordado	o time, agora
`warn`	funciona, mas está estranho	o time, depois
`info`	o caminho normal	quem precisa do histórico
`debug`	só desenvolvimento	quem está depurando

O debug é o nível que não existe em produção, e o filtro é o NODE_ENV: com ele em producao, o mínimo gravado passa a ser info, e o debug sai do volume junto com o payload e o tamanho da requisição. A informação fica, o barulho sai.

E o inverso também vale: o error que não acorda ninguém é o que treina o time a ignorar error. A diferença entre "logar tudo" e "logar o que importa" é o que separa um log consultado de um log enterrado.

`ds_request_id` é o que correlaciona requisições

Sem identificador, o log é um rio: mil linhas de requisições diferentes misturadas, e a única forma de achar a sua é ler tudo procurando hora parecida. Com o id da requisição repetido em toda linha daquela requisição, a pergunta "o que essa requisição fez?" vira uma contagem:

SELECT ds_request_id, COUNT(*) AS linhas
FROM tb_log GROUP BY ds_request_id

Isso é correlacionar requisições, e é o que separa o erro de uma pessoa do erro de todo mundo. O exemplo grava cinco linhas de uma requisição só — info, warn, warn, debug, error — e a contagem devolve 5 linhas, 1 error, 2 warn. Quem gera o id novo a cada requisição é a aula 2, com crypto.randomUUID(); aqui ele é fixo, para a saída ser idêntica a cada execução.

Log sem dado sensível: a máscara

O ponto onde o log vaza é o corpo da requisição. Um log de acesso que imprime o corpo inteiro registra a senha do usuário num texto que o banco guarda, o arquivo guarda e o backup guarda.

A regra é: o log precisa servir para achar o problema, e o problema quase nunca é a senha. Então o log guarda o comprimento e os últimos 4 caracteres, que bastam para dizer "é a mesma senha de ontem":

function mascara(valor, visiveis = 4) {
  const texto = String(valor ?? '');
  if (texto.length === 0) return '(vazio)';
  if (texto.length <= visiveis) return '*'.repeat(texto.length);
  return '*'.repeat(texto.length - visiveis) + texto.slice(-visiveis);
}

O email no log é um caso diferente do token no log, e a diferença é útil. O token é segredo e some inteiro. O domínio do e-mail não é segredo, e dizer "o erro é de um cliente só" vale mais do que esconder. O que não entra é a parte do local, que identifica a pessoa:

function mascaraEmail(email) {
  const corte = String(email ?? '').indexOf('@');
  return String(email).slice(0, 1) + '***' + String(email).slice(corte);
}

A prova de que a máscara funciona é o banco, não o código: a linha gravada é lida de volta e mostrada inteira. Uma senha de 19 caracteres aparece com 15 asteriscos e 4 letras — os 4 últimos, nunca os primeiros.

console.log é transitório e às vezes some em restart. As duas saídas de verdade são o log em arquivo e o stdout capturado pelo gerenciador de processo, e as duas recebem o mesmo JSON.stringify no mesmo ponto do código — por isso a função de log é uma função só, e não um console.log espalhado.

debug também vaza: o payload inteiro em debug é o caminho mais curto para a senha no arquivo de log. Lista de chaves e comprimento resolvem a depuração; o valor é o que vaza.

A máscara é para o dado que o usuário mandou e que você não pode devolver. A senha do banco continua vindo do .env, e o valor do .env não entra em log nenhum.

Nível não substitui contexto: um error sem rota e sem codigo_mysql diz que algo quebrou, e um info com a rota e o identificador diz exatamente onde. As duas coisas juntas é que a linha responde pergunta.

Exemplo

'use strict';

// Exemplo da aula 1 do dia 13: log que responde pergunta.
//
// A tese da aula: log nao e "jogar texto no arquivo". E uma linha que responde
// uma pergunta concreta sem precisar abrir o servidor. Para isso sao quatro
// campos estruturados e um carimbo de tempo:
//
//   1. st_nivel      — error / warn / info / debug
//   2. ds_request_id — o MESMO em todas as linhas da mesma requisicao
//   3. ds_mensagem   — o que aconteceu, em uma frase
//   4. ds_contexto   — JSON com o resto (rota, status, codigo do MySQL)
//   5. tempo         — carimbado pelo proprio banco, nao pelo codigo
//
// O quinto campo e o detalhe que quase todo mundo faz errado. A funcao NAO
// gera hora: e o `horario no log` que o `DEFAULT CURRENT_TIMESTAMP` da coluna
// coloca, e o stdout capturado pelo gerenciador ja vem prefixado. Duas fontes
// de tempo brigando produzem um log que mente sobre quando o evento aconteceu.
//
// O caso que o exemplo executa de verdade e o do dado sensivel: um corpo de
// requisicao com senha, token e e-mail. A funcao `mascara` deixa passar so os
// 4 ultimos caracteres, e o exemplo imprime a linha JA MASCARADA. O valor
// original nao vai para o banco, nao vai para o stdout e nao aparece em lugar
// nenhum do material.
//
// O identificador de requisicao aqui e FIXO de proposito (`req-demo-7f3a`):
// com ele a saida e identica toda vez que o exemplo roda. Quem gera um
// `id da requisicao` novo a cada requisicao, com `crypto.randomUUID()`, e a
// aula 2.
//
// A conexao vem do harness do material (`await conexao`). Este exemplo nao
// segura um servidor HTTP, entao a conexao compartilhada da para ele e o
// proprio harness a fecha quando a ultima consulta termina. A aula 2, que
// segura um servidor enquanto responde, abre a conexao dela mesma.

const NIVEL_ORDEM = { debug: 10, info: 20, warn: 30, error: 40 };

// O `nivel de log` nao e decoracao: e a resposta para "isso acorda alguem?".
// `NODE_ENV` decide o que e gravado. Sem ele (desenvolvimento) entra ate
// `debug`; com `producao`, `debug` deixa de existir e o volume de log cai.
const AMBIENTE = process.env.NODE_ENV || 'desenvolvimento';
const NIVEL_MINIMO = AMBIENTE === 'producao' ? 'info' : 'debug';

function deveGravar(nivel, minimo = NIVEL_MINIMO) {
  return (NIVEL_ORDEM[nivel] ?? 0) >= (NIVEL_ORDEM[minimo] ?? 0);
}

// ================================================ 1. nunca logar dado sensivel
// A regra do `log sem dado sensivel`: o log precisa servir para achar o
// problema, e o problema quase nunca e a senha. Entao o log guarda o
// COMPRIMENTO e os ultimos caracteres, que bastam para dizer "e a mesma senha
// de ontem", e nao o valor. O `token no log` e o `email no log` seguem a
// mesma regra por caminhos diferentes: o token some inteiro, o e-mail guarda
// o dominio e perde o local.
function mascara(valor, visiveis = 4) {
  const texto = String(valor ?? '');
  if (texto.length === 0) return '(vazio)';
  if (texto.length <= visiveis) return '*'.repeat(texto.length);
  return '*'.repeat(texto.length - visiveis) + texto.slice(-visiveis);
}

// E-mail e diferente de senha: o dominio NAO e segredo e ajuda muito no log
// (da para saber se o erro e so de um cliente). O que nao entra e a parte do
// local, que identifica a pessoa.
function mascaraEmail(email) {
  const texto = String(email ?? '');
  const corte = texto.indexOf('@');
  if (corte < 1) return '(invalido)';
  return texto.slice(0, 1) + '***' + texto.slice(corte);
}

// Um segredo de exemplo, montado na hora. O exemplo precisa de um valor que
// pareca senha e token para a mascara ter o que mascarar, mas o VALOR nao pode
// estar escrito no arquivo: em aplicacao de verdade ele vem do `.env`
// (CONTRATO.md), e um literal no codigo vai parar no git. Aqui e sintetico.
function segredoDeExemplo(rotulo) {
  return ['valor', 'de', rotulo].join('-');
}

// ===================================================== 2. a linha de log
// Uma funcao, e nao um `console.log` espalhado: e ela que decide o nivel, monta
// o JSON, aplica a mascara e grava no banco. Um log que depende de cada um
// lembrar de mascarar e um log que vaza na primeira vez que alguem esquece.
//
// O `log estruturado` e o `log em JSON` sao a MESMA linha: o `JSON.stringify`
// vai para o stdout E para a coluna `ds_contexto`, no mesmo ponto. E o
// `log com contexto` que diz `onde o erro aconteceu` — sem ele, a linha sabe
// que algo quebrou e nao sabe onde.
async function registrar(conn, { nivel, requestId, mensagem, contexto = {} }) {
  if (!deveGravar(nivel)) return null;

  const linha = { nivel, request_id: requestId, mensagem, contexto };
  console.log(JSON.stringify(linha));

  const [gravado] = await conn.execute(
    'INSERT INTO tb_log (st_nivel, ds_request_id, ds_mensagem, ds_contexto) '
    + 'VALUES (?, ?, ?, ?)',
    [nivel, requestId, mensagem, JSON.stringify(contexto)]
  );
  return gravado.insertId;
}

// =========================================================== 3. o programa
async function main() {
  const conn = await conexao;

  // `IF NOT EXISTS` + `TRUNCATE`: o exemplo roda varias vezes e tem de dar o
  // mesmo resultado. O `TRUNCATE` zera tambem o AUTO_INCREMENT, entao o `id`
  // das linhas impressas comeca sempre em 1.
  //
  // O indice de `ds_request_id` ja nasce dentro do CREATE TABLE. Fica assim
  // de proposito: um `ALTER TABLE ... ADD KEY` separado quebraria na segunda
  // execucao, porque o nome do indice ja existiria.
  await conn.query(`
    CREATE TABLE IF NOT EXISTS tb_log (
      id            INT AUTO_INCREMENT PRIMARY KEY,
      dt_registro   DATETIME     NOT NULL DEFAULT CURRENT_TIMESTAMP,
      st_nivel      VARCHAR(10)  NOT NULL,
      ds_request_id VARCHAR(40)  NOT NULL,
      ds_mensagem   VARCHAR(120) NOT NULL,
      ds_contexto   JSON         NULL,
      KEY ix_tb_log_req (ds_request_id)
    ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
  `);
  await conn.query('TRUNCATE TABLE tb_log');

  // O indice e o que faz a busca da aula 2 (`WHERE ds_request_id = ?`) nao
  // varrer a tabela inteira.
  const [ix] = await conn.query(
    "SELECT index_name, seq_in_index, column_name FROM information_schema.statistics "
    + "WHERE table_schema = DATABASE() AND table_name = 'tb_log' "
    + "AND index_name = 'ix_tb_log_req' ORDER BY seq_in_index"
  );
  console.log('--- 0. a tabela do log ---');
  console.log('indice ix_tb_log_req sobre: ' + ix.map((i) => i.column_name).join(', '));
  console.log('sem esse indice, a busca da aula 2 leria a tabela inteira');

  // Um identificador so por requisicao, repetido em TODA linha daquela
  // requisicao. E o que permite correlacionar: quantas linhas, em que ordem.
  const REQ = 'req-demo-7f3a';

  console.log('\n--- 1. os quatro niveis, e o que cada um promete ---');
  console.log('ambiente NODE_ENV: ' + AMBIENTE
    + ' — nivel minimo gravado: ' + NIVEL_MINIMO);

  await registrar(conn, {
    nivel: 'info',
    requestId: REQ,
    mensagem: 'requisicao recebida',
    contexto: { metodo: 'POST', rota: '/login', ip: '203.0.113.10' },
  });

  await registrar(conn, {
    nivel: 'warn',
    requestId: REQ,
    mensagem: 'tentativa de login recusada',
    contexto: { motivo: 'senha nao confere', tentativas_na_minuta: 2 },
  });

  // --------------------------------------------------------- dado sensivel
  // O corpo CHEGA inteiro, e por isso a mascara existe. Repare que o valor de
  // `senha`, `token` e `nm_email` nao e impresso em lugar nenhum: o que sai
  // no stdout e no banco e a versao mascarada.
  //
  // Os valores sao montados na hora por `segredoDeExemplo()`, e nao escritos
  // aqui: um segredo literal no arquivo e um segredo que vai parar no git. O
  // que a aula precisa e que eles EXISTAM e sejam mascarados, nao que valham
  // alguma coisa.
  const corpoRecebido = {
    nm_user: 'ana',
    nm_email: '[email protected]',
    senha: segredoDeExemplo('material'),
    token: segredoDeExemplo('token'),
  };

  await registrar(conn, {
    nivel: 'warn',
    requestId: REQ,
    mensagem: 'credencial recusada no login',
    contexto: {
      rota: '/login',
      ds_usuario: corpoRecebido.nm_user,
      ds_senha: mascara(corpoRecebido.senha),
      ds_token: mascara(corpoRecebido.token),
      ds_email: mascaraEmail(corpoRecebido.nm_email),
    },
  });

  await registrar(conn, {
    nivel: 'debug',
    requestId: REQ,
    mensagem: 'payload recebido, antes da validacao',
    contexto: {
      chaves: Object.keys(corpoRecebido),
      bytes: JSON.stringify(corpoRecebido).length,
      // Os VALORES nao vao para o log de debug tambem. Lista de chave e
      // comprimento bastam para depurar; valor e o que vaza.
      valores: '(nao logado)',
    },
  });

  // ------------------------------------------------------- erro de verdade
  // Um `error` aqui tem que ser um erro que aconteceu de verdade, e nao uma
  // frase. O par `console.error` + `console.log` e o que o CONTRATO.md exige:
  // o terminal mostra o erro, a pagina tambem, e a linha de contexto vem
  // ANTES para a pagina nao mostrar um erro solto.
  console.log('\n--- 2. error: consulta a uma tabela que nao existe ---');
  console.log('vou rodar: SELECT * FROM tb_item_inexistente');
  try {
    await conn.query('SELECT * FROM tb_item_inexistente');
  } catch (erro) {
    console.error(erro.code + ': ' + erro.message);
    console.log('  erro capturado:', erro.code, '- nivel error, alguem e avisado');
    await registrar(conn, {
      nivel: 'error',
      requestId: REQ,
      mensagem: 'falha ao montar relatorio de itens',
      contexto: {
        codigo_mysql: erro.code,          // e o que se compara, nao a message
        etapa: 'montar relatorio',
        sql: 'SELECT * FROM tb_item_inexistente',
      },
    });
  }

  // ------------------------------------------------------------- a leitura
  console.log('\n--- 3. o log gravado, lido de volta do banco ---');
  const [linhas] = await conn.query(
    'SELECT id, st_nivel, ds_request_id, ds_mensagem, ds_contexto '
    + 'FROM tb_log ORDER BY id'
  );
  console.log('linhas em tb_log: ' + linhas.length);
  for (const l of linhas) {
    const ctx = typeof l.ds_contexto === 'string'
      ? JSON.parse(l.ds_contexto) : l.ds_contexto;
    console.log('  id=' + l.id + '  ' + l.st_nivel.padEnd(5)
      + '  ' + l.ds_mensagem);
    console.log('      contexto: ' + JSON.stringify(ctx));
  }

  // A linha da mascara, mostrada como saiu do banco: e a unica forma de
  // provar que a senha nao esta la. Se alguem rodar e vir a senha inteira
  // nesta saida, a mascara foi quebrada.
  const [mascarada] = await conn.query(
    'SELECT ds_mensagem, ds_contexto FROM tb_log '
    + 'WHERE ds_request_id = ? AND ds_mensagem = ?',
    [REQ, 'credencial recusada no login']
  );
  const ctx = typeof mascarada[0].ds_contexto === 'string'
    ? JSON.parse(mascarada[0].ds_contexto) : mascarada[0].ds_contexto;
  console.log('\n--- 4. a linha que tem credencial, como ficou no banco ---');
  console.log(JSON.stringify(ctx, null, 2));
  const mascarados = ctx.ds_senha.split('*').length - 1;
  console.log('a senha original tem ' + corpoRecebido.senha.length
    + ' caracteres; no log sobram ' + (ctx.ds_senha.length - mascarados)
    + ' e ' + mascarados + ' viram asterisco');
  console.log('os 4 que sobram sao os ULTIMOS da senha, nao os primeiros');
  console.log('o dominio do e-mail ficou: e o que separa "erro do cliente"');
  console.log('de "erro nosso" — sem a parte que identifica a pessoa');

  // ----------------------------------------------------- correlacionar (tema)
  // Quantas linhas tem por requisicao. E `correlacionar requisicoes`: a
  // pergunta "o que essa requisicao fez?" vira uma contagem, sem abrir o
  // servidor e sem ler o log inteiro.
  console.log('\n--- 5. correlacionar: linhas por requisicao ---');
  const [porReq] = await conn.query(
    'SELECT ds_request_id, COUNT(*) AS linhas, '
    + "SUM(st_nivel = 'error') AS erros, "
    + "SUM(st_nivel = 'warn') AS avisos "
    + 'FROM tb_log GROUP BY ds_request_id ORDER BY ds_request_id'
  );
  for (const g of porReq) {
    console.log('  ' + g.ds_request_id + ' -> ' + g.linhas
      + ' linhas, ' + g.erros + ' error, ' + g.avisos + ' warn');
  }
  console.log('duas requisicoes distintas dariam dois numeros distintos: e assim');
  console.log('que se sabe se o erro foi de UMA pessoa ou de todo mundo');

  // --------------------------------------------------------- filtro de nivel
  // A mesma lista de eventos, com o filtro de producao aplicado. E o que
  // muda quando o volume de log incomoda: o `debug` deixa de ser gravado, e o
  // `info`/`warn`/`error` continuam — que sao os que respondem pergunta.
  console.log('\n--- 6. o filtro: o que entraria em producao ---');
  const eventos = ['debug', 'info', 'warn', 'error'];
  for (const minimo of ['debug', 'info']) {
    const passam = eventos.filter((n) => deveGravar(n, minimo));
    console.log('  nivel minimo ' + minimo.padEnd(5) + ' -> grava: '
      + passam.join(', '));
  }
  console.log('em producao o `debug` sai do volume, e com ele o `payload` e os');
  console.log('bytes da requisicao: a informacao fica, o barulho nao');

  // ------------------------------------------------------------ o carimbo
  // Prova de que a hora veio do banco e nao do codigo: as linhas tem
  // `dt_registro` preenchido, e nenhuma delas foi carimbada pela funcao.
  const [hora] = await conn.query(
    'SELECT COUNT(*) AS total, COUNT(dt_registro) AS com_hora FROM tb_log'
  );
  console.log('\n--- 7. onde a hora entrou ---');
  console.log('linhas: ' + hora[0].total + ', com dt_registro preenchido: '
    + hora[0].com_hora);
  console.log('a funcao `registrar` nao monta data nem hora: quem carimba e o');
  console.log('DEFAULT CURRENT_TIMESTAMP da coluna. O stdout do processo, que o');
  console.log('gerenciador ja prefixa, e a segunda fonte — o arquivo de log');

  // A versao do banco nunca e escrita a mao: o exemplo pergunta e imprime.
  // Repare no `[0]`: `query` devolve `[linhas, campos]`, e a destructuracao
  // `const [versao]` entrega o ARRAY de linhas, nao a linha.
  const [versao] = await conn.query('SELECT VERSION() AS versao');
  console.log('\nbanco em uso: ' + versao[0].versao);
}

main().catch((erro) => {
  console.error('falhou:', erro.code || erro.name, '-', erro.message);
  process.exit(1);
});

Saída real

--- 0. a tabela do log ---
indice ix_tb_log_req sobre: ds_request_id
sem esse indice, a busca da aula 2 leria a tabela inteira

--- 1. os quatro niveis, e o que cada um promete ---
ambiente NODE_ENV: desenvolvimento — nivel minimo gravado: debug
{"nivel":"info","request_id":"req-demo-7f3a","mensagem":"requisicao recebida","contexto":{"metodo":"POST","rota":"/login","ip":"203.0.113.10"}}
{"nivel":"warn","request_id":"req-demo-7f3a","mensagem":"tentativa de login recusada","contexto":{"motivo":"senha nao confere","tentativas_na_minuta":2}}
{"nivel":"warn","request_id":"req-demo-7f3a","mensagem":"credencial recusada no login","contexto":{"rota":"/login","ds_usuario":"ana","ds_senha":"*************rial","ds_token":"**********oken","ds_email":"a***@exemplo.com"}}
{"nivel":"debug","request_id":"req-demo-7f3a","mensagem":"payload recebido, antes da validacao","contexto":{"chaves":["nm_user","nm_email","senha","token"],"bytes":99,"valores":"(nao logado)"}}

--- 2. error: consulta a uma tabela que nao existe ---
vou rodar: SELECT * FROM tb_item_inexistente
  erro capturado: ER_NO_SUCH_TABLE - nivel error, alguem e avisado
{"nivel":"error","request_id":"req-demo-7f3a","mensagem":"falha ao montar relatorio de itens","contexto":{"codigo_mysql":"ER_NO_SUCH_TABLE","etapa":"montar relatorio","sql":"SELECT * FROM tb_item_inexistente"}}

--- 3. o log gravado, lido de volta do banco ---
linhas em tb_log: 5
  id=1  info   requisicao recebida
      contexto: {"metodo":"POST","rota":"/login","ip":"203.0.113.10"}
  id=2  warn   tentativa de login recusada
      contexto: {"motivo":"senha nao confere","tentativas_na_minuta":2}
  id=3  warn   credencial recusada no login
      contexto: {"rota":"/login","ds_usuario":"ana","ds_senha":"*************rial","ds_token":"**********oken","ds_email":"a***@exemplo.com"}
  id=4  debug  payload recebido, antes da validacao
      contexto: {"chaves":["nm_user","nm_email","senha","token"],"bytes":99,"valores":"(nao logado)"}
  id=5  error  falha ao montar relatorio de itens
      contexto: {"codigo_mysql":"ER_NO_SUCH_TABLE","etapa":"montar relatorio","sql":"SELECT * FROM tb_item_inexistente"}

--- 4. a linha que tem credencial, como ficou no banco ---
{
  "rota": "/login",
  "ds_usuario": "ana",
  "ds_senha": "*************rial",
  "ds_token": "**********oken",
  "ds_email": "a***@exemplo.com"
}
a senha original tem 17 caracteres; no log sobram 4 e 13 viram asterisco
os 4 que sobram sao os ULTIMOS da senha, nao os primeiros
o dominio do e-mail ficou: e o que separa "erro do cliente"
de "erro nosso" — sem a parte que identifica a pessoa

--- 5. correlacionar: linhas por requisicao ---
  req-demo-7f3a -> 5 linhas, 1 error, 2 warn
duas requisicoes distintas dariam dois numeros distintos: e assim
que se sabe se o erro foi de UMA pessoa ou de todo mundo

--- 6. o filtro: o que entraria em producao ---
  nivel minimo debug -> grava: debug, info, warn, error
  nivel minimo info  -> grava: info, warn, error
em producao o `debug` sai do volume, e com ele o `payload` e os
bytes da requisicao: a informacao fica, o barulho nao

--- 7. onde a hora entrou ---
linhas: 5, com dt_registro preenchido: 5
a funcao `registrar` nao monta data nem hora: quem carimba e o
DEFAULT CURRENT_TIMESTAMP da coluna. O stdout do processo, que o
gerenciador ja prefixa, e a segunda fonte — o arquivo de log

banco em uso: 10.11.14-MariaDB-0ubuntu0.24.04.1

Aula 2

Achar o erro pelo identificador

Procurado por identificador único ID de requisição rastrear rastreabilidade achar requisição pelo ID endpoint de saúde health check métrica uptime quantidade de erro alerta saber que quebrou monitorar

O identificador que atravessa a requisição

Sem identificador, o cliente escreve "deu erro" e começa uma conversa: que erro, em que tela, que hora, o que você fez antes. Cada resposta vem outra pergunta. Com um ID de requisição gerado na entrada, ele escreve uma frase — o id — e a conversa acaba.

O caminho tem cinco passos, e a ordem importa porque é a ordem em que a requisição acontece:

crypto.randomUUID() gera o identificador único na entrada;
o valor entra no log, e todas as linhas daquela requição carregam o mesmo;
o erro.code e o stack vão para o log com esse id;
a resposta HTTP sai com o cabeçalho X-Request-Id;
o cliente lê o cabeçalho, e a busca é WHERE ds_request_id = ?.

A rastreabilidade é o nome do que os cinco passos produzem: rastrear a partir de uma frase do usuário até a linha exata do banco.

O X-Request-Id que o cliente manda também é respeitado — é assim que o id atravessa CDN, gateway e mais de um serviço sem se perder. Mas ele é texto livre, e texto livre dentro de um campo de cabeçalho é um furo: qualquer um manda 4 KB ali dentro. Por isso o servidor só aceita o que tem formato de UUID e substitui o resto:

const FORMATO_UUID = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i;

function idDaRequisicao(req) {
  const recebido = req.headers['x-request-id'];
  if (typeof recebido === 'string' && FORMATO_UUID.test(recebido)) {
    return { id: recebido, origem: 'cliente' };
  }
  return { id: crypto.randomUUID(), origem: 'servidor' };
}

Um curl -i mostra o cabeçalho saindo:

const resposta = await fetch(base + '/saude');
console.log('X-Request-Id na resposta: ' + resposta.headers.get('x-request-id'));

A resposta do exemplo traz o id em três lugares — o cabeçalho, o corpo e o log — e os três com o mesmo valor. Quando o cliente reportar o problema, ele manda esse id e o time não precisa perguntar mais nada.

Achar requisição pelo ID é uma busca indexada

O ds_request_id tem índice na tabela, e o índice é o que torna a busca barata:

SELECT id, st_nivel, ds_mensagem, ds_contexto
FROM tb_log WHERE ds_request_id = ? ORDER BY id

A busca pelo id da requisição que quebrou devolve só as linhas dela — duas, no exemplo: a linha info da entrada e a linha error com o codigo_mysql, a etapa e o stack. A mesma consulta com um id que nunca aconteceu devolve zero linha, e é isso que prova que o filtro filtra: não é "as últimas linhas do log", é a requisição pedida.

O EXPLAIN confirma que o planejador usou o índice:

EXPLAIN SELECT id FROM tb_log WHERE ds_request_id = ?

Sem o índice, a mesma busca lê a tabela inteira. Com ele, a diferença é entre "achar o erro" e "esperar dois minutos para achar o erro".

O 500 não pode devolver o stack

A tentação é devolver a mensagem do erro para facilitar. É exatamente o que vaza. O corpo de um erro de banco carrega o código, o nome da tabela e o SQL — informação que descreve a estrutura interna para quem não deveria conhecer, e que vira mapa de ataque.

O corpo do 500 do exemplo tem três campos, e nenhum deles é o erro:

{
  "erro": "ER_INTERNO",
  "mensagem": "recurso indisponivel",
  "request_id": "identificador-que-muda-a-cada-execucao"
}

O request_id é um UUID novo a cada execução do exemplo, porque cada requisição recebe o seu. É o único valor da página que muda entre uma rodada e outra, e ele muda por desenho — um id fixo seria o oposto de identificador único.

ER_INTERNO é um código seu, não do MySQL. mensagem é o que o cliente pode mostrar para o usuário final sem explicar nada da sua arquitetura. request_id é a ponte: com ele, quem recebe o erro encontra o erro.code verdadeiro no log, em segundos, e o time inteiro continua com o que importa.

A tradução de erro.code é o que permite isso. O erro.code é o que a aplicação compara; o texto é o que o usuário vê:

const TRADUCAO = {
  ER_DUP_ENTRY: 'registro ja existe',
  ER_NO_REFERENCED_ROW: 'referencia invalida',
  ER_NO_SUCH_TABLE: 'recurso indisponivel',
  ER_DATA_TOO_LONG: 'campo maior que o permitido',
};

function traduzirErro(erro) {
  return TRADUCAO[erro && erro.code] || 'erro interno, ja registramos para investigacao';
}

ER_NO_SUCH_TABLE no exemplo é o caso que mostra o motivo: traduzido, vira "recurso indisponivel"; cru, ele entrega o nome da tabela. E o status também sai da tradução, porque "a pessoa mandou coisa errada" e "nos quebramos" têm respostas diferentes: ER_DUP_ENTRY é 409, ER_DATA_TOO_LONG é 400, e qualquer código fora da lista é 500.

O stack vai para o log, e enxuto: caminho absoluto da máquina de quem rodou e número de linha que muda a cada edição são ruído no meio do que importa. Guardar a primeira linha do erro.stack mais o nome do arquivo já responde "onde o erro aconteceu" sem vazar o diretório do servidor.

Endpoint de saúde: o que monitora e o que acorda

O endpoint de saúde (/saude, ou health check) responde se o processo está vivo e se o banco responde. Os dois, e não só o processo: MySQL parado com Node no ar passa em qualquer verificação que olhe só o processo, e a API está fora do ar de todo modo.

const [saude] = await conn.query('SELECT 1 AS vivo');
res.end(JSON.stringify({
  estado: saude[0].vivo === 1 ? 'saudavel' : 'instavel',
  banco: saude[0].vivo === 1 ? 'respondendo' : 'sem resposta',
  request_id: id,
}));

O uptime é a métrica do outro lado: ela diz que o serviço responde, e não que ele faz o que deveria. As duas juntas fecham o quadro.

O que acorda alguém não é o evento isolado, é a quantidade de erro por janela — e é isso que permite monitorar e saber que quebrou sem ninguém olhar tela:

SELECT st_nivel, COUNT(*) AS total, COUNT(DISTINCT ds_request_id) AS reqs
FROM tb_log GROUP BY st_nivel

O COUNT(DISTINCT ds_request_id) é o número que separa os dois incidentes que parecem iguais: três error de uma pessoa só é uma conta com senha errada; três error de três pessoas é o sistema fora. O mesmo total de linhas,oum problema completamente diferente — e só o DISTINCT diz qual dos dois é.

Header de rastreio é X-Request-Id por convenção, mas o nome é seu: o que importa é que o mesmo valor saia na resposta e entre no log. Se um proxy intermediário reescreve o cabeçalho, a correlação morre ali — e é por isso que o id vai também no corpo.

Cliente que reporta erro deve copiar o id da tela, não digitá-lo. Erro de digitação transforma uma busca de um segundo em uma conversa inteira de suporte.

Alerta por volume absoluto erra dos dois lados: alerta em todo warn acorda alguém toda noite, e alerta em contagem alta de error espera o sistema cair. O alerta útil é taxa por janela: quantidade de error por minuto acima do normal, com o id da requisição de exemplo anexado para o time começar pelo meio.

Log com --inspect ligado em produção abre uma porta de depuração na rede. É o mesmo cuidado do dado sensível: o que o log ajuda a diagnosticar também vaza para quem lê, e quem lê pode não ser você.