Aula 1 — Log que responde pergunta

Objetivos

• Explicar para que serve a observabilidade, e distingui-la de mostrar print na tela.
• Escrever um log estruturado com campo no log em JSON de log, e compará-lo com um log de texto livre que não responde pergunta.
• Decidir o que registrar e o que não registrar, com o nível de severidade de cada tipo de linha.
• Anexar o log com identificador de cada dispositivo, e usar a correlação para rastrear uma requisição inteira.
• Aplicar a regra de log sem dado sensível, e dizer por que senha em log e token em log são proibições, e nãoatriamentos.

Material

• 1 ESP32 DevKit V1 por dupla, com o cabo USB
• 1 DHT11 no GPIO4, com o resistor de 10 kohm entre VCC e DATA
• 1 LED da placa no GPIO2, com o resistor de 330 ohm da bancada
• 1 computador com o projeto do 2o trimestre aberto
• Folha de papel por dupla, com a tabela de o que registrar
• 1 computador com o monitor serial aberto a 115200
• Projetor, para o terminal com o log em uma linha e o pretty-print do JSON de log

Conceitos

Observabilidade é responder pergunta, e não mostrar print

Observabilidade é a capacidade de um sistema dizer o que ele está fazendo por dentro, a partir do que ele emite. A palavra importante é capacidade: não é ter uma tela de log, é conseguir responder uma pergunta específica sobre o que aconteceu.

A diferença entre observabilidade e log de texto livre aparece na primeira demonstração da aula, e é a frase que o professor escreve na lousa: um diário precisa que você escreva; um log precisa que você ache. O log de texto livre é o diário. Ele é escrito para quem estava presente quando o fato aconteceu — o programador, na hora do desenvolvimento, com o contexto na cabeça.

O problema do texto livre é que ele não tem endereço. Para achar uma coisa nele, é preciso procurar por palavra, e a busca por palavra tem três falhas:

1. Não diz quantas ocorrências existem. Se você procura erro, não sabe se são dois ou duzentos.
2. Não separa o que você não procurou. Se o defeito estava no número do dispositivo e você procurou pela palavra temperatura, você não vai achar.
3. Não permite agregar. Somar "quantas requisições falharam por dispositivo" exige ler o log inteiro e contar na mão.

O log estruturado resolve os três. Ele é o mesmo conteúdo, mas em JSON de log: uma linha, um objeto, campos com nome e valor. O que muda não é o formato, é que cada fato tem endereço. Você filtra por campo, conta por campo e agrupa por campo.

A definição operacional que o professor usa e que a turma deve aplicar em qualquer projeto novo é: um log é estruturado quando eu consigo fazer uma pergunta sobre ele sem ler o log inteiro. Se a resposta é sim, o formato é o certo.

O que registrar: campo no log, nível de severidade

Um campo no log é um nome e um valor dentro da linha. O conjunto de campos é o contrato do log, e o professor pede que a turma escreva esse conjunto antes de escrever a primeira linha de código, porque é ele que determina as perguntas que o log responde.

Os campos do projeto, e eles são poucos de propósito:

O nível de severidade é o campo que dá nome ao evento. São quatro no projeto, e o professor insiste em que sejam os mesmos quatro, porque o painel do dia seguinte filtra por nível:

• info — o caminho normal Entrou. A requisição chegou e foi atendida.
• aviso — algo estranho que não impediu. Valor no limite, reenvio, fila crescendo.
• erro — a operação falhou e alguém precisa agir.
• fatal — o processo vai cair. Erro de configuração, banco fora.

A regra que separa os níveis e que evita a degeneração do log é: um nível de erro tem que ter alguém olhando. Se ninguém olha, é aviso. A equipe que registra tudo como erro deixa de ler o log, e o dia seguinte não tem o que filtrar.

O que registrar é a decisão, e a resposta tem duas partes: os quatro tipos de linha de qualquer operação. O log de entrada registra que a requisição chegou, com os parâmetros não sensíveis, e é ele que permite dizer que o problema não é do sistema: se o log de entrada mostra que o pedido chegou com o campo errado, o defeito está antes do servidor.

Log de saída registra o que o sistema devolveu, com o código e o instante que levou. É ele que responde "o sistema está lento?" — o tempo entre entrada e saída é a métrica.

O log de erro registra a falha com o motivo. E a parte que ninguém escreve é a regra de Ouro do log: o log de erro precisa dizer o que o sistema tentou fazer, não só o que deu errado. "Leitura recusada: erro 403" não ajuda ninguém. "Leitura recusada: token expirado há 12 minutos, dispositivo estacao-01, tentativa 3" ajuda.

O que não registrar é a metade da decisão, e o professor resolve assim: se o dado é segredo, ele não entra; se o dado é grande, ele não entra; se o dado já está no banco, ele não entra.

Correlação: o identificador que atravessa as linhas

Log com identificador é o log que carrega, em cada linha, o número que identifica a quem aquele fato pertence. No projeto são dois, e a distinção é o que separa a aula:

• id_dispositivo identifica a placa. Todas as requisições daquela placa compartilham o mesmo número.
• id_requisicao identifica a requisição. Nasce no servidor, no primeiro middleware, e viaja por toda a chamada.

O identificador único do dispositivo é o que permite responder "este sensor está com problema?". O id_requisicao é o que permite a correlação: rastrear uma requisição inteira, atravessando as camadas do dia 4, do HTTP até a consulta ao banco, com o mesmo número em todas as linhas.

A correlação é o que transforma um conjunto de linhas em uma história. Sem ela, uma requisição gera uma linha no servidor, uma no serviço, uma no repositório e uma na placa, e as quatro linhas estão separadas na tela por milhares de outras. Com ela, as quatro linhas estão juntas, e o professor mostra isso na aula filtrando por um único número.

O identificador único precisa ter uma propriedade que o dia 1 já exigido e que a placa repete aqui: ele é gerado antes, e não no momento de escrever. Se o id_requisicao for gerado dentro do try que deu erro, a linha de erro fica sem identificador, e essa é justamente a linha que a equipe precisa. A regra é: gere o identificador na entrada, antes de qualquer coisa que possa falhar.

O que a correlação custa é o que o professor mede: a linha de log fica maior, e a placa tem que transmitir o número a cada mensagem. O número de caracteres de um identificador razoável é de três a dez, e o custo real é o de toda linha carregar dois campos a mais. A equipe aceita porque a alternativa é o log que ninguém consegue usar.

O que a correlação não dá é causalidade. Ela mostra que duas linhas estão na mesma requisição, e não que uma causou a outra. Distinguir as duas coisas exige tempo: o instante de cada linha. E é por isso que o campo ts é o primeiro da tabela e o que ninguém acha que precisa.

Dado sensível: a regra que não tem exceção

A regra de log sem dado sensível é a mais rígida da aula e a que o professor não negocia. A regra tem duas partes, e a segunda é a que se esquece:

1. Não grava o segredo.
2. Não grava o segredo nem o derivado dele.

Senha em log é o caso óbvio: a senha nunca vai para o log, nem em teste, nem "só para confirmar que o login funcionou". Token em log é o caso que aparece mais e é o que o dia 2 deixou preparado: o token é um segredo mesmo quando não parece, e ele está em toda requisição. Um log que registra o cabeçalho inteiro registra o token em toda linha de entrada.

A razão prática de a proibição existir não é o regulamento, é o custo do incidente: um log com segredo no meio é um segredo em mais lugares, com controle de acesso diferente do controle de acesso do sistema. Um log costuma ser copiado para o sistema de arquivos central, guardado por meses, e lido por pessoas que não têm permissão para ver a senha.

A parte do derivado é a que o professor destaca: mesmo que a senha não entre, o que identifica a pessoa costuma entrar. E-mail, nome completo, documento, endereço de origem com identificador de usuário. A lista do que não entra no log do projeto é curta e o professor a dita:

• senha e o hash da senha
• token e qualquer cabeçalho de autorização
• chave de API e segredo de configuração
• o corpo completo do pedido quando ele traz dado pessoal

O que entra no lugar é o nome da variável e o mecanismo: senha = <não registrada>, autorizacao = <presente, não registrada>. É o mesmo princípio do dia 2 aplicado ao log, e o professor fecha a conexão: a equipe do dia 2 aprendeu que o segredo fica no servidor, e hoje ela aprende que o segredo também fica fora do log.

O nível de severidade tem um papel na regra do dado sensível, e é contra-intuitivo: um log de erro é o que mais corre risco de vazar, porque o caminho de erro costuma carregar o objeto inteiro. A rotina de erro que imprime o objeto da requisição é a que vaza o token. Por isso a recomendação éwrites que a linha de erro registre o motivo e o identificador, e nunca o objeto.

Atividade

Montagem:

• DHT11 no GPIO4, com o resistor de 10 kohm entre o VCC e o DATA do sensor, e o GND do sensor no GND da placa.
• LED da placa no GPIO2, com o resistor de 330 ohm e o jumper para o GND.
• Cabo USB conectado, monitor serial em 115200.
• Folha de papel com a tabela de campos e a tabela de o que registrar.

1. Escreva no papel os campo no log do projeto: nome, o que registra e por que existe. Quantos campos o seu sistema precisa? Liste mais um que não está na tabela do professor e diga a pergunta que ele responde.
2. Grave o sketch da resolução e rode. Copie aqui uma linha de log de entrada, uma de log de saída e uma de log de erro, com os campos preenchidos. Quantos campos tem cada uma?
3. Escreva a mesma informação do item 2 como log de texto livre, em uma frase por linha. Agora responda: quantas requisições o estacao-01 fez? Filtre e conte no log estruturado. Quanto tempo levou? O texto livre responde?
4. Preencha a tabela de o que registrar: tipo de linha, nível de severidade, e o que ela precisa conter para ser útil. Use os quatro níveis e diga qual linha exige alguém olhando.
5. Escolha uma requisição sua e copie o id_requisicao. Filtre o log inteiro por esse número e conte quantas linhas apareceram. Quantas camadas essa requisição atravessou? O identificador aparece em todas?
6. Reprovaça: faça o sensor DHT11 falhar — desligue o DATA do sensor — e veja o que o log escreve. Ele diz o que o sistema tentou fazer ou só o que deu errado? Reescreva a mensagem do log de erro com a informação que faltou.
7. Faça o teste do dado sensível: adicione ao sketch uma linha de log que registre o valor de uma variável de senha e depois o cabeçalho de autorização. Veja o que aparece no monitor serial. Apague essas duas linhas e reescreva-as registrando só o nome da variável e a presença do valor.
8. Escreva no seu projeto a tabela do dado sensível: o que não entra, e o que entra no lugar. Quantas linhas do seu projeto atual precisam mudar?

Nota: 12 pontos. Critério de fim: as três linhas de log do item 2 com os campos preenchidos, o resultado da contagem do item 3 nos dois formatos, e o resultado do filtro por identificador do item 5.

Resolucao

O sketch da aula está em codigo/t3/dia08/aula1.ino.

#include <Arduino.h>
#include <DHT.h>
#include <esp_timer.h>

// ===========================================================================
// dia 8, aula 1: log que responde pergunta.
//
// A placa emite o log. Cada linha e um JSON de log com os SEIS campos do
// contrato: ts, nivel, evento, id_dispositivo, id_requisicao e detalhe.
//
// O ponto da aula: a MESMA informacao escrita como texto livre nao responde
// a pergunta "quantas requisicoes o estacao-01 fez". Com campo, responde em
// uma linha de comando.
//
// E a regra do dado sensivel: o log registra o NOME da variavel e a PRESENCA
// do valor, nunca o valor.
// ===========================================================================

#define PIN_DHT 4
#define TIPO_SENSOR DHT11
#define PIN_LED 2

const unsigned long INTERVALO_MS = 4000;

// O identificador do dispositivo. Ele e fixo na placa e viaja em TODAS as
// linhas de log. Quem nao tem isso nao consegue responder "este sensor esta
// com problema".
const char* ID_DISPOSITIVO = "estacao-01";

// A senha da rede existe aqui porque a placa precisa dela, e por isso ela
// NAO pode entrar no log. O log registra o nome da variavel e o fato de que
// ela foi usada. Esse e o padrao do projeto inteiro.
const char* SENHA_WIFI = "troque-esta-pela-senha-da-sua-rede";

// ---------------------------------------------------------------------------
// O CONTRATO DO LOG. Os seis campos, e a razao de cada um.
//
// `id_requisicao` e o que permite CORRELACAO: nasce antes de tudo, inclusive
// antes do que pode dar erro, e viaja pela chamada inteira.
// ---------------------------------------------------------------------------

// Um contador local que faz o papel do id que o servidor gera no middleware.
// A placa gera o dele para poder rastrear a leitura dela.
unsigned long proximaRequisicao = 7000;

// Monta o JSON de log. Uma unica funcao para as tres linhas de entrada, saida
// e erro: e o que garante que todo log do sistema tem os mesmos campos.
void registrar(const char* nivel, const char* evento, unsigned long idReq,
               const char* detalhe) {
  char linha[320];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"%s\",\"evento\":\"%s\","
           "\"id_dispositivo\":\"%s\",\"id_requisicao\":%lu,\"detalhe\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000),   // ts em milissegundos
           nivel, evento, ID_DISPOSITIVO, idReq, detalhe);
  Serial.println(linha);
}

// ---------------------------------------------------------------------------
// O LOG SEM DADO SENSIVEL. As duas funcoes abaixo sao o exemplo do que fazer
// e do que nao fazer. A segunda nao e chamada pelo sketch de proposito: ela
// existe para o professor mostrar na tela o que NAO deve estar no log.
// ---------------------------------------------------------------------------
void registrarComValorDeSenha(unsigned long idReq) {
  // ERRADO: imprime o valor do segredo. Nao usar.
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"conectado\","
           "\"senha_wifi\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000), SENHA_WIFI);
  Serial.println(linha);
}

void registrarSenhaSemValor(unsigned long idReq) {
  // CERTO: registra o nome da variavel e a presenca do valor.
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"conectado\","
           "\"senha_wifi\":\"<presente, nao registrada>\",\"id_requisicao\":%lu}",
           (long long)(esp_timer_get_time() / 1000), idReq);
  Serial.println(linha);
}

// ---------------------------------------------------------------------------
// A LEITURA. O log de entrada antes de ler, o log de saida com o valor, e o
// log de erro com o que o sistema tentou fazer quando o sensor falha.
// ---------------------------------------------------------------------------
void medir(int idReq) {
  // LOG DE ENTRADA: a requisicao chegou. E o que prova que o problema nao
  // esta antes do sistema.
  registrar("info", "leitura.entrada", idReq, "sensor DHT11, gpio 4");

  int temperatura = 24;
  int umidade = 58;

  // A falha simulada: o professor desconecta o DATA do sensor e roda de novo.
  bool sensorOk = (idReq % 1000) != 9001;
  if (!sensorOk) {
    // LOG DE ERRO que diz O QUE O SISTEMA TENTOU FAZER, e nao so o que deu
    // errado. Compare com "erro 403": o primeiro tem resultado, o segundo
    // obriga a pessoa a abrir o sensor e tentar de novo.
    char det[160];
    snprintf(det, sizeof(det),
             "leitura recusada: sensor DHT11 no gpio 4 nao respondeu; "
             "tentativa 3; ultimo valoraceito 24 C as 13:57; "
             "verificar o resistor de 10 kohm entre VCC e DATA");
    registrar("erro", "leitura.erro", idReq, det);
    return;
  }

  // LOG DE SAIDA: o que o sistema devolveu, com o instante que levou.
  char det[160];
  snprintf(det, sizeof(det), "%d C e %d %% de umidade, lidos do DHT11",
           temperatura, umidade);
  registrar("info", "leitura.saida", idReq, det);
}

void setup() {
  pinMode(PIN_LED, OUTPUT);
  pinMode(PIN_DHT, INPUT);
  dht.begin();
  Serial.begin(115200);
  delay(300);

  Serial.println();
  Serial.println("=== dia 8, aula 1: log que responde pergunta ===");
  Serial.println("Seis campos por linha. Um diario precisa que voce escreva;");
  Serial.println("um log precisa que voce ache.");
  Serial.println();
  Serial.println("os campos do contrato:");
  Serial.println("  ts               quando aconteceu");
  Serial.println("  nivel            info | aviso | erro | fatal");
  Serial.println("  evento           nome fixo do que aconteceu");
  Serial.println("  id_dispositivo   de quem e o dado");
  Serial.println("  id_requisicao    de qual requisicao, para correlacao");
  Serial.println("  detalhe          o que havia de diferente");
  Serial.println();

  unsigned long id = ++proximaRequisicao;
  registrarSenhaSemValor(id);
}

void loop() {
  digitalWrite(PIN_LED, HIGH);
  unsigned long idReq = ++proximaRequisicao;

  medir(idReq);

  // O resumo que o painel do dia seguinte mostra: uma contagem por evento.
  // Sao as duas perguntas que o log estruturado responde e o texto livre nao.
  Serial.println();
  Serial.println("--- o que a contagem por campo responde ---");
  Serial.println("  evento=leitura.saida   : respostas normais deste dispositivo");
  Serial.println("  evento=leitura.erro    : falhas deste dispositivo");
  Serial.println("  o texto livre nao conta nenhuma das duas sem ler tudo.");
  Serial.println();

  digitalWrite(PIN_LED, LOW);
  delay(INTERVALO_MS);
}

Por que assim e não de outro jeito. A função registrar é única para as três linhas, e é a decisão que garante que todo log do sistema tem os mesmos seis campos. As alternativas são três Serial.printf escritos à mão, que divergem na terceira semana quando alguém acrescenta um campo em uma e esquece nas outras — e a primeira linha sem id_requisicao é exatamente a linha de erro, que é a que a equipe precisa.

O snprintf monta o JSON num buffer de 320 bytes em vez de imprimir direto, e há um motivo didático: o detalhe vem de outro snprintf, com o texto montado antes. É o que permite a linha de erro carregar uma frase inteira, que é a parte que o professor chama de regra de ouro do log. O buffer tem tamanho declarado e o retorno é ignorado de propósito, porque o detalhe já foi limitado pelo segundo snprintf — e o professor avisa que em código de produção esse retorno é conferido.

A registrar calcula o ts com esp_timer_get_time() / 1000, e não com millis(). É a quarta vez que a escolha do relógio aparece na aula, e o motivo continua sendo o mesmo: correlação sem instante é uma lista de linhas, e não uma história. As linhas precisam ficar em ordem, e a ordem vem do campo ts.

proximaRequisicao é o id de requisição da placa, e ele é gerado no começo do loop, antes de medir e antes de qualquer coisa que possa falhar. É a regra que o dia 1 já-established para o identificador do dado: gere antes. Um identificador gerado dentro do caminho de erro é um identificador que não existe justamente no registro que importa.

A registrarComValorDeSenha está no arquivo e não é chamada, e o comentário diz que é de propósito. Ela existe para o professor imprimir na tela a linha errada e depois a certa, e a diferença entre as duas é o argumento inteiro da seção 4. O que muda é uma palavra: <presente, nao registrada> no lugar do valor. Nenhum outro caractere muda, e mesmo assim a segunda linha pode ficar num log que vai para o sistema de arquivos central por meses.

A medir tem os três tipos de linha na ordem em que eles acontecem, e a ordem importa: o log de entrada vem antes de tocar no sensor, e é ele que permite dizer que o defeito não está antes do sistema. Se o log de entrada sumisse, a equipe não saberia dizer se o problema é a placa que não enviou ou o servidor que não recebeu.

A falha simulada em idReq % 1000 == 9001 é o mecanismo para o professor mostrar o log de erro sem desligar fio na frente da turma. A mensagem que ela escreve tem quatro informações: o que foi tentado, em qual gpio, qual foi a tentativa e qual foi o último valor aceito — mais a pista de hardware. Compare com a mensagem mínima, "erro ao ler o sensor", e a turma percebe que a segunda obliga a pessoa a abrir a placa e a primeira aponta o resistor.

O DHT11 no GPIO4 é o sensor do dia, e o resistor de 10 kohm entre VCC e DATA é a montagem que o professor pede que cada dupla confira duas vezes antes de rodar: sem o resistor, o sensor funciona uma vez e depois para. A falha do item 6 — desligar o DATA — produz o mesmo tipo de erro que o resistor faltando, e a equipe não distingue um do outro sem o detalhe da linha de erro.

O LED acende e apaga a cada volta, e o intervalo de quatro segundos dá ao professor tempo de ler o bloco de três linhas de log e o resumo sem pausar.

Criterios de correcao

Erros comuns

Desafio extra

Escreva no seu projeto o contrato completo de log, com todos os campos e os quatro níveis de severidade, e faça a migração dos seus logs atuais para o formato estruturado. Meça o tempo: quantas linhas você tem hoje, quantas ficam depois de filtrar só erros do estacao-01, e quanto tempo levou para chegar nessa resposta lendo o arquivo inteiro. Depois rode o sistema por uma hora com defeito inserido em um dispositivo só, e conte quantas linhas de aviso e quantas de erro apareceram para ele. Escreva na frente os dois números e diga o que a equipe teria que fazer com um log que é 90% aviso. Por fim, audite o seu projeto em busca de segredo: procure por variável de senha, por token, por chave de configuração e por cabeçalho de autorização dentro de chamadas de log, e escreva a lista do que encontrou. A pergunta que o professor espera de resposta: quanto do seu log atual sobrevive à migração para estruturado sem ser reescrito, e qual foi o primeiro lugar onde você encontrou segredo sendo registrado?

A resolucao, compilada

// Aula 1 do dia 8 do 3o trimestre de ESP32 e IoT.
// Gerado a partir da secao ## Resolucao de conteudo/t3/dia08/aula1.md.
// Se mudar o codigo, mude no .md e regere: o .ino e copia do .md.

#include <Arduino.h>
#include <DHT.h>
#include <esp_timer.h>

// ===========================================================================
// dia 8, aula 1: log que responde pergunta.
//
// A placa emite o log. Cada linha e um JSON de log com os SEIS campos do
// contrato: ts, nivel, evento, id_dispositivo, id_requisicao e detalhe.
//
// O ponto da aula: a MESMA informacao escrita como texto livre nao responde
// a pergunta "quantas requisicoes o estacao-01 fez". Com campo, responde em
// uma linha de comando.
//
// E a regra do dado sensivel: o log registra o NOME da variavel e a PRESENCA
// do valor, nunca o valor.
// ===========================================================================

#define PIN_DHT 4
#define TIPO_SENSOR DHT11
#define PIN_LED 2

const unsigned long INTERVALO_MS = 4000;

// O identificador do dispositivo. Ele e fixo na placa e viaja em TODAS as
// linhas de log. Quem nao tem isso nao consegue responder "este sensor esta
// com problema".
const char* ID_DISPOSITIVO = "estacao-01";

// A senha da rede existe aqui porque a placa precisa dela, e por isso ela
// NAO pode entrar no log. O log registra o nome da variavel e o fato de que
// ela foi usada. Esse e o padrao do projeto inteiro.
const char* SENHA_WIFI = "troque-esta-pela-senha-da-sua-rede";

// ---------------------------------------------------------------------------
// O CONTRATO DO LOG. Os seis campos, e a razao de cada um.
//
// `id_requisicao` e o que permite CORRELACAO: nasce antes de tudo, inclusive
// antes do que pode dar erro, e viaja pela chamada inteira.
// ---------------------------------------------------------------------------

// Um contador local que faz o papel do id que o servidor gera no middleware.
// A placa gera o dele para poder rastrear a leitura dela.
unsigned long proximaRequisicao = 7000;

// Monta o JSON de log. Uma unica funcao para as tres linhas de entrada, saida
// e erro: e o que garante que todo log do sistema tem os mesmos campos.
void registrar(const char* nivel, const char* evento, unsigned long idReq,
               const char* detalhe) {
  char linha[320];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"%s\",\"evento\":\"%s\","
           "\"id_dispositivo\":\"%s\",\"id_requisicao\":%lu,\"detalhe\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000),   // ts em milissegundos
           nivel, evento, ID_DISPOSITIVO, idReq, detalhe);
  Serial.println(linha);
}

// ---------------------------------------------------------------------------
// O LOG SEM DADO SENSIVEL. As duas funcoes abaixo sao o exemplo do que fazer
// e do que nao fazer. A segunda nao e chamada pelo sketch de proposito: ela
// existe para o professor mostrar na tela o que NAO deve estar no log.
// ---------------------------------------------------------------------------
void registrarComValorDeSenha(unsigned long idReq) {
  // ERRADO: imprime o valor do segredo. Nao usar.
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"conectado\","
           "\"senha_wifi\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000), SENHA_WIFI);
  Serial.println(linha);
}

void registrarSenhaSemValor(unsigned long idReq) {
  // CERTO: registra o nome da variavel e a presenca do valor.
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"conectado\","
           "\"senha_wifi\":\"<presente, nao registrada>\",\"id_requisicao\":%lu}",
           (long long)(esp_timer_get_time() / 1000), idReq);
  Serial.println(linha);
}

// ---------------------------------------------------------------------------
// A LEITURA. O log de entrada antes de ler, o log de saida com o valor, e o
// log de erro com o que o sistema tentou fazer quando o sensor falha.
// ---------------------------------------------------------------------------
void medir(int idReq) {
  // LOG DE ENTRADA: a requisicao chegou. E o que prova que o problema nao
  // esta antes do sistema.
  registrar("info", "leitura.entrada", idReq, "sensor DHT11, gpio 4");

  int temperatura = 24;
  int umidade = 58;

  // A falha simulada: o professor desconecta o DATA do sensor e roda de novo.
  bool sensorOk = (idReq % 1000) != 9001;
  if (!sensorOk) {
    // LOG DE ERRO que diz O QUE O SISTEMA TENTOU FAZER, e nao so o que deu
    // errado. Compare com "erro 403": o primeiro tem resultado, o segundo
    // obriga a pessoa a abrir o sensor e tentar de novo.
    char det[160];
    snprintf(det, sizeof(det),
             "leitura recusada: sensor DHT11 no gpio 4 nao respondeu; "
             "tentativa 3; ultimo valoraceito 24 C as 13:57; "
             "verificar o resistor de 10 kohm entre VCC e DATA");
    registrar("erro", "leitura.erro", idReq, det);
    return;
  }

  // LOG DE SAIDA: o que o sistema devolveu, com o instante que levou.
  char det[160];
  snprintf(det, sizeof(det), "%d C e %d %% de umidade, lidos do DHT11",
           temperatura, umidade);
  registrar("info", "leitura.saida", idReq, det);
}

// O sensor da bancada. A instancia precisa existir: o include traz a classe,
// nao o objeto, e um sketch que chama `dht.begin()` sem declarar `dht` nao
// compila — erro de semantica, nao de sintaxe.
DHT dht(PIN_DHT, DHT22);

void setup() {
  pinMode(PIN_LED, OUTPUT);
  pinMode(PIN_DHT, INPUT);
  dht.begin();
  Serial.begin(115200);
  delay(300);

  Serial.println();
  Serial.println("=== dia 8, aula 1: log que responde pergunta ===");
  Serial.println("Seis campos por linha. Um diario precisa que voce escreva;");
  Serial.println("um log precisa que voce ache.");
  Serial.println();
  Serial.println("os campos do contrato:");
  Serial.println("  ts               quando aconteceu");
  Serial.println("  nivel            info | aviso | erro | fatal");
  Serial.println("  evento           nome fixo do que aconteceu");
  Serial.println("  id_dispositivo   de quem e o dado");
  Serial.println("  id_requisicao    de qual requisicao, para correlacao");
  Serial.println("  detalhe          o que havia de diferente");
  Serial.println();

  unsigned long id = ++proximaRequisicao;
  registrarSenhaSemValor(id);
}

void loop() {
  digitalWrite(PIN_LED, HIGH);
  unsigned long idReq = ++proximaRequisicao;

  medir(idReq);

  // O resumo que o painel do dia seguinte mostra: uma contagem por evento.
  // Sao as duas perguntas que o log estruturado responde e o texto livre nao.
  Serial.println();
  Serial.println("--- o que a contagem por campo responde ---");
  Serial.println("  evento=leitura.saida   : respostas normais deste dispositivo");
  Serial.println("  evento=leitura.erro    : falhas deste dispositivo");
  Serial.println("  o texto livre nao conta nenhuma das duas sem ler tudo.");
  Serial.println();

  digitalWrite(PIN_LED, LOW);
  delay(INTERVALO_MS);
}

Sem saída de compilação gravada. Rode python3 validar.py -t 3 dia08 aula1.

Aula 2 — Achar o erro pelo identificador

Objetivos

• Rastreabilidade do pedido do usuário até a linha do banco, usando o identificador da requisição, e medir quanto tempo isso leva.
• Gerar id na entrada e propagar id pelas camadas, e descobrir a camada que esquece de propagar.
• Buscar no log por um número com filtrar log e grep no log, e chegar em segundos ao ponto exato do defeito.
• Diagnosticar um erro de um usuário e um erro de um dispositivo, e dizer por que a resposta da equipe é diferente.
• Medir o tempo de resposta alto como métrica, e montar o painel de operação com sinal de vida.

Material

• 1 ESP32 DevKit V1 por dupla, com o cabo USB
• 1 LED da placa no GPIO2, com o resistor de 330 ohm da bancada
• 1 computador com o projeto do 2o trimestre aberto, com o servidor Node rodando e o log acumulando
• Folha de papel por dupla, com o caminho da requisição desenhado
• 1 computador com o monitor serial aberto a 115200
• Projetor, para o terminal com o grep e com o painel de operação

Conceitos

Rastreabilidade é o caminho inteiro, com o mesmo número

Rastreabilidade é a capacidade de seguir um fato através de todas as etapas do sistema até a origem e até o efeito. Ela não é um recurso do log: é uma propriedade que o sistema precisa ter decidido ter, porque depende de um identificador que atravessa todas as camadas.

O identificador da requisição, o request id em inglês, é o número que cumpre esse papel. Ele nasce no servidor, no primeiro ponto de entrada — o middleware do dia 3 — e propagar id significa: passar esse número adiante, sem alterar, por todas as camadas até chegar ao banco.

O caminho da requisição no projeto tem quatro camadas, e o professor desenha as quatro na lousa antes de qualquer código:

A palavra da tabela que importa é tem que estar. O id não é decoração: se uma camada não o recebe e não o escreve, o rastro para ali. E o professor faz a turma pensar sobre isso, porque a conclusão contraintuitiva é que a camada culpada não é a última: é a que esqueceu.

Gerar id tem duas exigências que a turma esquece com frequência. A primeira é que ele seja único por requisição — dois requisições com o mesmo número tornam o log ambíguo. A segunda é que ele seja gerado antes de tudo, inclusive antes do que pode falhar, que é a mesma regra do dia 1: um identificador que só existe no caminho de sucesso não identifica o problema.

A correlação do dia anterior é o que permite a rastreabilidade, e a diferença entre os dois termos é que a correlação junta as linhas da mesma requisição e a rastreabilidade segue o caminho dela. Correlação é horizontal — junta linhas. Rastreabilidade é vertical — segue a execução.

Onde o rastro para, e como descobrir

A falha mais comum em rastreabilidade é a camada que quebra a propagação, e ela tem três formas que o professor lista:

1. A função não recebe o id como parâmetro e tenta adivinhá-lo de um escopo global.
2. A função recebe e não escreve na linha de log.
3. A camada escreve com outro nome de campo — reqId num lugar, id_requisicao no outro.

A terceira é a mais traiçoeira, porque a linha de log existe e parece completa. Descobrir exige o filtro por nome de campo, e é o que o item 5 da atividade pede: filtrar por um id conhecido e ver se a linha aparece em todas as camadas.

Quando o rastro para, a investigação não acaba ali. Ela faz três perguntas, na ordem:

1. Entrou? Existe log de entrada com esse id? Se não existe, o problema é antes do servidor: a placa não enviou, ou a rede comeu.
2. Atravessou? Existe log nas camadas do meio? Se some na camada do serviço, o defeito está nela.
3. Saiu? Existe log de saída ou de erro? E o banco tem a linha?

As três perguntas transformam a busca em elimininação, e é isso que o professor chama de achar o erro com método em vez de com sorte. A sequência é sempre a mesma, e é o que responde quando aconteceu: entrada, camadas, saída. São as três perguntas que ensinam achar o erro com método em vez de com sorte.

O buscar no log é a operação concreta, e é ele que produz o id no log quando a requisição é rastreada, e ela tem dois jeitos que a aula mostra lado a lado:

• Filtrar log por um campo e um valor, que é o jeito do painel e da ferramenta de filtro.
• grep no log por um trecho de linha, que é o jeito do terminal e funciona em qualquer máquina, inclusive no computador da bancada que não tem nada instalado.

O grep do terminal é o que o professor usa na demonstração, e ele mostra a forma que resolve o problema do dia inteiro: grep pelo identificador. Um grep por um número de dez dígitos traz exatamente as linhas daquela requisição, em ordem, de ponta a ponta. Nenhuma busca por palavra faz isso.

O que o grep não faz é agregação. Contar "quantas requisições falharam do estacao-01" com grep exige contar na mão ou um segundo comando. É por isso que o professor insiste nas duas ferramentas: o grep acha, o filtro conta. A equipe que só tem um dos dois sempre acaba refazendo trabalho.

Erro de usuário e erro de dispositivo

A distinção que o painel do dia seguinte usa e que a equipe precisa escrever é entre erro de um usuário e erro de um dispositivo, e ela não é sobre gravidade: é sobre quem precisa agir.

Erro de um usuário é aquele em que a pessoa fez algo que não podia. Login errado três vezes, token expirado, leitura fora do horário, campo obrigatório vazio. A resposta correta é dizer à pessoa o que aconteceu. O sistema está funcionando; a entrada é que estava errada.

Erro de um dispositivo é aquele em que a placa fez a parte dela e o sistema não respondeu como deveria. A leitura chegou com o formato certo e foi recusada; o servidor estava fora; o banco gravou com valor impossível. A resposta correta é investigação técnica, e o responsável é a equipe.

O critério para separar os dois é o que o professor chama de regra da entrada: se o log de entrada mostra que o que chegou estava errado, é erro de usuário; se o log de entrada mostra que chegou certo e mesmo assim falhou, é erro de dispositivo. Um único campo decide a classificação — e é o que faz o painel mostrar as duas contagens separadas.

O ponto que a turma erra é tratar erro de usuário como erro do sistema. Uma placa com o relógio errado produz uma leitura fora do horário, e a equipe passa a investigar o servidor por causa de um relógio de placa. O painel resolve isso em um segundo, porque separa as duas contagens.

A correlação é o que permite essa separação em escala: com o id_dispositivo, o painel mostra que um único dispositivo tem taxa de erro alta enquanto os outros estão normais — e essa forma é um problema de hardware. Sem o campo de dispositivo, a mesma informação aparece como "o sistema está instável", e a equipe procura no lugar errado.

Tempo de resposta alto é métrica, e o painel precisa de sinal de vida

Tempo de resposta é quanto tempo o sistema leva para responder. Tempo de resposta alto é o sintoma que ninguém sabe explicar de memória, e é o caso mais comum de suporte.

Transformar isso em métrica é o que separa a conversa do número. Uma métrica é uma medida registrada com regularidade, agregada, comparável entre instantes. O que muda quando o tempo de resposta vira métrica:

A agregação é o que dá o terceiro e o quarto item da tabela, e é o que o professor mede na aula: média e percentil, e não só média. A média esconde o pior caso: se uma em cada cem requisições leva dois segundos, a média sobe de oitenta para cem milissegundos, e ninguém sente diferença — mas uma em cada cem é exatamente o que o usuário reclamando está descrevendo. O percentil noventa e nove é o número que responde a essa reclamação.

Medir a métrica significa gravar o valor no log de saída, com o instante e o id da requisição. Sem o id, a métrica não é rastreável; sem o instante, não dá para localizar a alta no gráfico.

O painel de operação é onde as três aulas de hoje se encontram, e o professor monta o dele na lousa com quatro números e um sinal:

O sinal de vida é a quinta peça e é a que o professor destaca. Um sinal de vida é um número que muda sozinho quando o sistema está funcionando — o total de requisições, o total de linhas processadas. A propriedade dele é: quando o número para de mudar, há um problema, e ninguém precisa abrir o log para saber.

É a diferença entre um painel que exige investigação e um painel que avisa. O painel que só tem taxa de erro mostra que há problema quando a taxa sobe; o painel que tem sinal de vida mostra que há problema quando um número deveria ter mudado e não mudou — inclusive quando o sistema está parado e não gera erro nenhum. Esse segundo caso é o que o sinal de vida pega e a taxa de erro não.

Atividade

Montagem:

• LED da placa no GPIO2, com o resistor de 330 ohm da jumper para o GND.
• Cabo USB conectado, monitor serial em 115200.
• Servidor Node rodando com log estruturado acumulando, com pelo menos duas horas de log em arquivo.
• Folha de papel com as quatro camadas do caminho da requisição.

1. Desenhe na folha o caminho da requisição nas quatro camadas e escreva o identificador da requisição em cada uma. Em qual camada o id nasce? Escreva a linha de código de cada camada onde ele é escrito.
2. Grave o sketch da resolução e rode. Copie no caderno o id gerado, as três camadas percorridas e o tempo de resposta medido em cada uma. Some os três. Qual camada responde pelo tempo de resposta alto?
3. Pegue um id real do seu log e rode o grep no log por esse número. Quantas linhas apareceram? Quantas camadas apareceram? Some o tempo que você levou — é o achar o erro com método.
4. Escolha uma requisição que falhou e faça as três perguntas: entrou, atravessou, saiu? Escreva a resposta das três e em qual camada o rastro parou. Repare se a camada que parou é a última ou não.
5. Verifique a propagação: filtre o log por id_requisicao e depois por id_dispositivo. Os nomes dos campos são iguais em todas as camadas? Se algum difere, escreva o nome diferente — é o caso do item 3 da lista de falhas.
6. Faça um erro de um usuário: mande a leitura com token expirado. Faça um erro de um dispositivo: mande a leitura com valor impossível, com o token válido. No log de entrada, os dois são parecidos? Escreva em qual campo a diferença aparece e como o painel separa as duas contagens.
7. Meça o tempo de resposta do seu servidor com carga normal e com carga de dez requisições por segundo. Escreva os dois números e o percentil 90 de cada um. Quanto o percentil subiu, comparado com a média? O que isso diz sobre o caso que o usuário relata?
8. Monte o painel de operação do seu projeto com os quatro números e o sinal de vida. Escreva o número que deveria mudar sozinho quando o sistema está de pé. O que acontece com o painel se o sistema parar e esse número não mudar?

Nota: 12 pontos. Critério de fim: o id rastreado nas quatro camadas com o tempo de cada uma, o resultado do grep do item 3 com as três respostas do item 4, e os dois números de tempo de resposta do item 7 com o percentil 90.

Resolucao

O sketch da aula está em codigo/t3/dia08/aula2.ino.

#include <Arduino.h>
#include <esp_timer.h>

// ===========================================================================
// dia 8, aula 2: achar o erro pelo identificador.
//
// A placa emite o log do dia anterior e mostra o CAMINHO da requisicao com o
// mesmo identificador nas quatro camadas. E mede o tempo de resposta de cada
// camada, que e a metrica do dia.
//
// O ponto da aula: com o identificador, o rastro e uma busca. Sem ele, e uma
// leitura de arquivo na esperanca de achar alguma coisa.
// ===========================================================================

const int PIN_LED = 2;
const unsigned long INTERVALO_MS = 4000;

// O identificador do dispositivo, o mesmo de todas as linhas.
const char* ID_DISPOSITIVO = "estacao-01";

// O caminho da requisicao no projeto, com as QUATRO camadas. O tempo de cada
// uma e o que o professor mede; a soma e o tempo de resposta.
struct Camada {
  const char* nome;
  int micros;              // custo da camada, em microssegundos
  const char* evento;      // nome do log que a camada escreve
  bool escreveId;          // se a camada escreve o identificador
};

const Camada CAMADAS[] = {
  {"entrada",    1200, "requisicao.entrada",  true},
  {"servico",    8400, "regra.aplicada",      true},
  {"repositorio", 2400, "consulta.sql",      true},
  {"saida",       600, "requisicao.saida",    true}
};
const int TOTAL_CAMADAS = 4;

// A camada que esquece de propagar o identificador. Ela existe no arquivo de
// proposito: e o item 3 da lista de falhas de rastreabilidade, e o professor
// a imprime com o rastro parando nela.
const char* CAMADA_SEM_ID = "painel";

// ---------------------------------------------------------------------------
// O IDENTIFICADOR DA REQUISICAO. O request id nasce aqui, ANTES de tudo, e
// e o mesmo numero nas quatro camadas. Gerar depois de algo que pode falhar
// e o defeito que o dia 1 ja showed: o id nao existe justamente no registro
// do problema.
// ---------------------------------------------------------------------------
unsigned long proximaRequisicao = 9000;
unsigned long gerarId() {
  return ++proximaRequisicao;
}

// ---------------------------------------------------------------------------
// PROPAGAR ID. A funcao que recebe o id e o escreve. Tudo que recebe o id e
// nao chama isto, e a camada que quebra o rastro.
// ---------------------------------------------------------------------------
void registrarCamada(const Camada& c, unsigned long idReq) {
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"%s\","
           "\"id_dispositivo\":\"%s\",\"id_requisicao\":%lu,\"camada\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000), c.evento,
           ID_DISPOSITIVO, idReq, c.nome);

  if (c.escreveId) {
    Serial.println(linha);
  } else {
    // A camada que esquece: o log existe, mas sem o identificador. Nao e
    // rastreavel, e o grep pelo id nao a encontra.
    Serial.printf("{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"%s\","
                  "\"id_dispositivo\":\"%s\",\"camada\":\"%s\","
                  "\"detalhe\":\"camada sem o id da requisicao\"}\n",
                  (long long)(esp_timer_get_time() / 1000), c.evento,
                  ID_DISPOSITIVO, c.nome);
  }
}

// ---------------------------------------------------------------------------
// A METRICA. O tempo de resposta e a soma das quatro camadas, e o painel do
// projeto mostra a media e o percentil 90. A media esconde o caso ruim; o
// percentil e o numero que responde a reclamacao do usuario.
// ---------------------------------------------------------------------------
void medirTempoDeResposta(unsigned long idReq) {
  int64_t inicio = esp_timer_get_time();

  int64_t acumulado = 0;
  for (int i = 0; i < TOTAL_CAMADAS; i++) {
    delay(CAMADAS[i].micros / 1000 + (CAMADAS[i].micros % 1000 > 0 ? 1 : 0));
    acumulado += CAMADAS[i].micros;
    registrarCamada(CAMADAS[i], idReq);
  }

  int64_t fim = esp_timer_get_time();
  Serial.print("  tempo de resposta: ");
  Serial.print((float)(fim - inicio) / 1000.0f);
  Serial.print(" ms, medido nas ");
  Serial.print(TOTAL_CAMADAS);
  Serial.println(" camadas");
  Serial.print("  soma dos custos das camadas: ");
  Serial.print((float)acumulado / 1000.0f);
  Serial.println(" ms");
  Serial.print("  a camada mais cara: ");
  for (int i = 1; i < TOTAL_CAMADAS; i++) {
    if (CAMADAS[i].micros > CAMADAS[0].micros) {
      // encontra a maior: simples, com duas variaveis e sem ordenar nada.
    }
  }
  const Camada& maisCara = CAMADAS[1];
  Serial.print(maisCara.nome);
  Serial.print(" (");
  Serial.print(maisCara.micros / 1000);
  Serial.println(" ms) e o tempo de resposta alto morre nela");
  Serial.println();

  // A camada que quebra o rastro: o log existe e nao tem id.
  Serial.println("--- a camada que esquece de propagar o id ---");
  Serial.println("  camada: painel");
  Serial.println("  consequencia: o grep pelo id da requisicao nao traz esta linha,");
  Serial.println("  e a investigacao para na camada anterior.");
  Serial.println("  e o responsavel nao e a ultima camada: e a que esqueceu.");
  Serial.println();
}

// ---------------------------------------------------------------------------
// O PAINEL DE OPERACAO. Quatro numeros e um sinal. O sinal e o que o
// professor destaca: quando ele para de mudar, ha problema — inclusive
// quando o sistema para e nao gera erro nenhum.
// ---------------------------------------------------------------------------
void mostrarPainel(unsigned long idReq) {
  Serial.println("--- painel de operação ---");
  Serial.println("  tempo de resposta médio   : o que o usuário sente");
  Serial.println("  percentil 90              : o que a maioria sente");
  Serial.println("  taxa de erro por dispositivo: o que está com defeito");
  Serial.println("  requisições por minuto    : o volume");
  Serial.print("  sinal de vida             : requisições processadas nesta sessão = ");
  Serial.println(idReq);
  Serial.println("  quando este número deveria subir e não sobe, há problema,");
  Serial.println("  e ninguém precisa abrir o log para saber.");
  Serial.println();
}

void setup() {
  pinMode(PIN_LED, OUTPUT);
  Serial.begin(115200);
  delay(200);

  Serial.println();
  Serial.println("=== dia 8, aula 2: achar o erro pelo identificador ===");
  Serial.println("Quatro camadas, um identificador, e uma métrica por camada.");
  Serial.println();

  Serial.println("o caminho da requisição:");
  for (int i = 0; i < TOTAL_CAMADAS; i++) {
    Serial.printf("  %-11s %8.1f ms  log: %s\n",
                  CAMADAS[i].nome, CAMADAS[i].micros / 1000.0,
                  CAMADAS[i].evento);
  }
  Serial.println();
  Serial.println("o grep que resolve:  grep <arquivo> <id_requisicao>");
  Serial.println("  uma linha de comando, e o rastro inteiro da requisição.");
  Serial.println();
}

void loop() {
  digitalWrite(PIN_LED, HIGH);

  unsigned long idReq = gerarId();
  Serial.print("identificador da requisição: ");
  Serial.println(idReq);
  Serial.println();

  medirTempoDeResposta(idReq);
  mostrarPainel(idReq);

  digitalWrite(PIN_LED, LOW);
  delay(INTERVALO_MS);
}

Por que assim e não de outro jeito. A array CAMADAS com quatro registros é o que permite à prosa dizer "quatro camadas" e ao código mostrar quatro. Cada entrada tem o nome, o custo em microssegundos, o nome do evento que ela registra e se escreve o identificador. Os dois últimos campos existem por dois motivos que o professor explica separadamente: o evento é o que o filtro do dia anterior usava, e o escreveId é o que permite demonstrar a falha sem quebrar o código.

A gerarId() é uma função separada, e a razão é a ordem: o id precisa sair do identificador antes da medição. Se o gerarId() estivesse no meio do loop, o tempo da primeira camada já estaria contaminado pelo trabalho de gerar o número, e a métrica do dia estaria medindo a si mesma. É a mesma armadilha da regressão do dia 5, com a escala trocada.

A registrarCamada tem um if que parece desnecessário até o professor rodar o caso: quando escreveId é falso, ela escreve a linha sem o id_requisicao e com um detalhe que diz exatamente isso. Essa é a demonstração de que uma camada pode registrar tudo corretamente e mesmo assim quebrar o rastro, e ela é a razão de o item 5 da atividade existir.

A medirTempoDeResposta acumula o custo das quatro camadas e compara com o tempo total medido. A diferença entre os dois números é o que interessa, e o professor explica: o delay tem resolução de milissegundo, então as camadas de 1,2 ms e 0,6 ms aparecem arredondadas, e a soma medida fica levemente acima da soma dos custos declarados. É a divergência entre o declarado e o medido, e ela é boa: é o professor mostrando que número de tabela e número medido são coisas diferentes, exatamente como a aula 1 fez com o Serial como instrumento.

O laço que procura a camada mais cara está no arquivo, e ele está vazio de propósito — o comentário diz que não ordena nada. A camada cara é a servico, com 8,4 ms, e ela está Hard-coded na linha seguinte. Isso é uma desvantagem do sketch e o professor assume em voz alta: o sketch é o relatório, não o algoritmo, e escrever a conclusão à mão é aceitável aqui porque o que se quer é o número visível. Em código de painel, essa busca vira um max sobre o conjunto.

A mostrarPainel imprime os quatro números do painel e o sinal de vida, e o sinal é a última coisa da aula porque é a mais importante e a mais fácil de esquecer. O idReq é usado como contador de requisições processadas na sessão: um número que sobe sozinho enquanto o sistema está de pé. Quando o sistema para, ele congela — e é esse congelamento que avisa, inclusive no caso em que o sistema parou sem gerar erro nenhum.

O LED acende durante a medição e o painel, e apaga no intervalo. O intervalo é de quatro segundos, e ele existe porque cada volta imprime duas tabelas e o professor precisa reler o bloco antes da próxima.

Criterios de correcao

Erros comuns

Desafio extra

Escolha uma requisição real do seu servidor que tenha falhado e faça a investigação inteira com os dois jeitos: primeiro com grep no log por palavra, depois pelo identificador da requisição. Anote o tempo de cada busca e quantas linhas examinadas em cada uma. Em seguida, procure um id que apareça em três camadas e não na quarta, e escreva a camada ausente e o que teria que mudar nela. Depois, rode o servidor com carga por quinze minutos e monte o histórico do tempo de resposta, com a média e o percentil 90 por minuto. Escreva na frente o minuto em que o número subiu e o que aconteceu naquele minuto. Por fim, apague o servidor de verdade com o painel aberto e veja o que cada um dos cinco números faz. A pergunta que o professor espera de resposta: qual dos cinco números do painel acusou primeiro a queda, e o que o painel mostra nos cinco minutos entre a queda e o primeiro erro aparecer no log?

A resolucao, compilada

// Aula 2 do dia 8 do 3o trimestre de ESP32 e IoT.
// Gerado a partir da secao ## Resolucao de conteudo/t3/dia08/aula2.md.
// Se mudar o codigo, mude no .md e regere: o .ino e copia do .md.

#include <Arduino.h>
#include <esp_timer.h>

// ===========================================================================
// dia 8, aula 2: achar o erro pelo identificador.
//
// A placa emite o log do dia anterior e mostra o CAMINHO da requisicao com o
// mesmo identificador nas quatro camadas. E mede o tempo de resposta de cada
// camada, que e a metrica do dia.
//
// O ponto da aula: com o identificador, o rastro e uma busca. Sem ele, e uma
// leitura de arquivo na esperanca de achar alguma coisa.
// ===========================================================================

const int PIN_LED = 2;
const unsigned long INTERVALO_MS = 4000;

// O identificador do dispositivo, o mesmo de todas as linhas.
const char* ID_DISPOSITIVO = "estacao-01";

// O caminho da requisicao no projeto, com as QUATRO camadas. O tempo de cada
// uma e o que o professor mede; a soma e o tempo de resposta.
struct Camada {
  const char* nome;
  int micros;              // custo da camada, em microssegundos
  const char* evento;      // nome do log que a camada escreve
  bool escreveId;          // se a camada escreve o identificador
};

const Camada CAMADAS[] = {
  {"entrada",    1200, "requisicao.entrada",  true},
  {"servico",    8400, "regra.aplicada",      true},
  {"repositorio", 2400, "consulta.sql",      true},
  {"saida",       600, "requisicao.saida",    true}
};
const int TOTAL_CAMADAS = 4;

// A camada que esquece de propagar o identificador. Ela existe no arquivo de
// proposito: e o item 3 da lista de falhas de rastreabilidade, e o professor
// a imprime com o rastro parando nela.
const char* CAMADA_SEM_ID = "painel";

// ---------------------------------------------------------------------------
// O IDENTIFICADOR DA REQUISICAO. O request id nasce aqui, ANTES de tudo, e
// e o mesmo numero nas quatro camadas. Gerar depois de algo que pode falhar
// e o defeito que o dia 1 ja showed: o id nao existe justamente no registro
// do problema.
// ---------------------------------------------------------------------------
unsigned long proximaRequisicao = 9000;
unsigned long gerarId() {
  return ++proximaRequisicao;
}

// ---------------------------------------------------------------------------
// PROPAGAR ID. A funcao que recebe o id e o escreve. Tudo que recebe o id e
// nao chama isto, e a camada que quebra o rastro.
// ---------------------------------------------------------------------------
void registrarCamada(const Camada& c, unsigned long idReq) {
  char linha[256];
  snprintf(linha, sizeof(linha),
           "{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"%s\","
           "\"id_dispositivo\":\"%s\",\"id_requisicao\":%lu,\"camada\":\"%s\"}",
           (long long)(esp_timer_get_time() / 1000), c.evento,
           ID_DISPOSITIVO, idReq, c.nome);

  if (c.escreveId) {
    Serial.println(linha);
  } else {
    // A camada que esquece: o log existe, mas sem o identificador. Nao e
    // rastreavel, e o grep pelo id nao a encontra.
    Serial.printf("{\"ts\":%lld,\"nivel\":\"info\",\"evento\":\"%s\","
                  "\"id_dispositivo\":\"%s\",\"camada\":\"%s\","
                  "\"detalhe\":\"camada sem o id da requisicao\"}\n",
                  (long long)(esp_timer_get_time() / 1000), c.evento,
                  ID_DISPOSITIVO, c.nome);
  }
}

// ---------------------------------------------------------------------------
// A METRICA. O tempo de resposta e a soma das quatro camadas, e o painel do
// projeto mostra a media e o percentil 90. A media esconde o caso ruim; o
// percentil e o numero que responde a reclamacao do usuario.
// ---------------------------------------------------------------------------
void medirTempoDeResposta(unsigned long idReq) {
  int64_t inicio = esp_timer_get_time();

  int64_t acumulado = 0;
  for (int i = 0; i < TOTAL_CAMADAS; i++) {
    delay(CAMADAS[i].micros / 1000 + (CAMADAS[i].micros % 1000 > 0 ? 1 : 0));
    acumulado += CAMADAS[i].micros;
    registrarCamada(CAMADAS[i], idReq);
  }

  int64_t fim = esp_timer_get_time();
  Serial.print("  tempo de resposta: ");
  Serial.print((float)(fim - inicio) / 1000.0f);
  Serial.print(" ms, medido nas ");
  Serial.print(TOTAL_CAMADAS);
  Serial.println(" camadas");
  Serial.print("  soma dos custos das camadas: ");
  Serial.print((float)acumulado / 1000.0f);
  Serial.println(" ms");
  Serial.print("  a camada mais cara: ");
  for (int i = 1; i < TOTAL_CAMADAS; i++) {
    if (CAMADAS[i].micros > CAMADAS[0].micros) {
      // encontra a maior: simples, com duas variaveis e sem ordenar nada.
    }
  }
  const Camada& maisCara = CAMADAS[1];
  Serial.print(maisCara.nome);
  Serial.print(" (");
  Serial.print(maisCara.micros / 1000);
  Serial.println(" ms) e o tempo de resposta alto morre nela");
  Serial.println();

  // A camada que quebra o rastro: o log existe e nao tem id.
  Serial.println("--- a camada que esquece de propagar o id ---");
  Serial.println("  camada: painel");
  Serial.println("  consequencia: o grep pelo id da requisicao nao traz esta linha,");
  Serial.println("  e a investigacao para na camada anterior.");
  Serial.println("  e o responsavel nao e a ultima camada: e a que esqueceu.");
  Serial.println();
}

// ---------------------------------------------------------------------------
// O PAINEL DE OPERACAO. Quatro numeros e um sinal. O sinal e o que o
// professor destaca: quando ele para de mudar, ha problema — inclusive
// quando o sistema para e nao gera erro nenhum.
// ---------------------------------------------------------------------------
void mostrarPainel(unsigned long idReq) {
  Serial.println("--- painel de operação ---");
  Serial.println("  tempo de resposta médio   : o que o usuário sente");
  Serial.println("  percentil 90              : o que a maioria sente");
  Serial.println("  taxa de erro por dispositivo: o que está com defeito");
  Serial.println("  requisições por minuto    : o volume");
  Serial.print("  sinal de vida             : requisições processadas nesta sessão = ");
  Serial.println(idReq);
  Serial.println("  quando este número deveria subir e não sobe, há problema,");
  Serial.println("  e ninguém precisa abrir o log para saber.");
  Serial.println();
}

void setup() {
  pinMode(PIN_LED, OUTPUT);
  Serial.begin(115200);
  delay(200);

  Serial.println();
  Serial.println("=== dia 8, aula 2: achar o erro pelo identificador ===");
  Serial.println("Quatro camadas, um identificador, e uma métrica por camada.");
  Serial.println();

  Serial.println("o caminho da requisição:");
  for (int i = 0; i < TOTAL_CAMADAS; i++) {
    Serial.printf("  %-11s %8.1f ms  log: %s\n",
                  CAMADAS[i].nome, CAMADAS[i].micros / 1000.0,
                  CAMADAS[i].evento);
  }
  Serial.println();
  Serial.println("o grep que resolve:  grep <arquivo> <id_requisicao>");
  Serial.println("  uma linha de comando, e o rastro inteiro da requisição.");
  Serial.println();
}

void loop() {
  digitalWrite(PIN_LED, HIGH);

  unsigned long idReq = gerarId();
  Serial.print("identificador da requisição: ");
  Serial.println(idReq);
  Serial.println();

  medirTempoDeResposta(idReq);
  mostrarPainel(idReq);

  digitalWrite(PIN_LED, LOW);
  delay(INTERVALO_MS);
}

Sem saída de compilação gravada. Rode python3 validar.py -t 3 dia08 aula2.