Registro de diagnóstico com o módulo JavaScript do NGINX

Liam CrillyDiretor Sênior de Gestão de Produtos

Solução de problemas em produção sem ajustar o log de erros

Editor – Este blog é um dos vários que abordam logs com o NGINX e o NGINX Plus. Veja também:

• Rastreamento de aplicações com NGINX e NGINX Plus
• Amostragem de requisições com o registro condicional do NGINX

Este também é um dos muitos blogs sobre casos de uso do módulo JavaScript do NGINX. Para ver a lista completa, consulte Casos de uso do módulo JavaScript do NGINX.

O NGINX ajuda organizações de todos os portes a manter em operação seus sites, aplicativos e APIs de missão crítica. Independentemente da escala e da infraestrutura de implantação escolhida, operar em produção não é fácil. Neste artigo, abordamos apenas um dos desafios de uma implantação em produção: o registro de logs. Mais especificamente, discutimos o equilíbrio necessário para coletar a quantidade certa de logs detalhados para a solução de problemas sem ficar sobrecarregado com dados desnecessários.

Noções básicas de logging

O NGINX oferece dois mecanismos diferentes de registro de logs: registro de acesso para solicitações de clientes e registro de erros para quando algo dá errado. Esses mecanismos estão disponíveis nos módulos HTTP e Stream (TCP/UDP), mas aqui nos concentramos no tráfego HTTP. (Há também um terceiro mecanismo de registro que usa o nível de severidade de depuração, mas não o abordaremos aqui.)

Uma configuração de log padrão típica do NGINX é semelhante a esta.

http {    
                      log_format  main  
                      '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';
 
    access_log /var/log/nginx/access.log main; # Log using the 'main' format
    error_log  /var/log/nginx/error.log  warn; # Log up to 'warn' severity level
    ...
}

A diretiva log_format descreve o conteúdo e a estrutura das entradas de log criadas quando a diretiva access_log é incluída na configuração. O exemplo acima é uma extensão do Common Log Format (CLF), usado por muitos servidores web. Com a diretiva error_log, você especifica o nível de severidade das mensagens a serem registradas, mas não o conteúdo nem o formato das entradas, que são fixos. Falaremos mais sobre isso na próxima seção.

Outros aspectos importantes dos logs do NGINX incluem:

• As diretivas de registro são herdadas automaticamente por contextos de configuração de nível inferior. Por exemplo, uma diretiva access_log no contexto http é aplicada a todos os blocos server{}.
• Uma diretiva de registro em um contexto filho substitui as diretivas herdadas.
• Várias diretivas de registro podem existir no mesmo contexto. Por exemplo, duas diretivas access_log podem ser usadas para criar tanto um arquivo de log CLF padrão quanto um segundo log mais detalhado.

A realidade dos logs em produção

Em termos gerais, queremos usar o log de acesso para fornecer análises e estatísticas de uso, e o log de erros para detectar falhas e solucionar problemas. No entanto, operar um sistema em produção raramente é tão simples assim. Veja alguns desafios comuns:

• Os logs de acesso não contêm detalhes suficientes para a solução de problemas
• Os logs de erro fornecem um bom nível de detalhamento no nível de severidade info, mas isso gera informações demais para operações normais
• O formato do log de erros é fixo e, portanto, não pode ser personalizado para incluir variáveis de interesse específico
• As entradas no log de erros não incluem o contexto da solicitação e são difíceis de correlacionar com a entrada correspondente no log de acesso

Além disso, alterar a configuração do NGINX para adicionar ou remover detalhes dos logs em um ambiente de produção também pode exigir a passagem por um processo de controle de alterações e a reimplantação da configuração. É totalmente seguro, mas um tanto trabalhoso ao solucionar um problema em tempo real, como: “por que estou observando um aumento repentino de erros 4xx/5xx?”. Isso, naturalmente, se torna ainda mais complexo quando há várias instâncias do NGINX processando o mesmo tráfego em um cluster.

Usando um segundo log de acesso para erros

Personalizar o formato do log de acesso para enriquecer os dados coletados em cada solicitação é uma abordagem comum para análises avançadas, mas não é uma solução escalável para diagnóstico ou solução de problemas. Fazer com que o log de acesso principal cumpra duas funções é uma solução forçada, pois normalmente precisamos de muito mais informações para solucionar problemas do que para análises regulares. Adicionar inúmeras variáveis ao log de acesso principal pode aumentar drasticamente o volume dos logs com dados que só são úteis ocasionalmente.

Instead we can use a second access log and write to it only when we encounter an error that warrants debugging. The access_log directive supports conditional logging with the if parameter – requests are only logged when the specified variable evaluates to a non‑zero, non‑empty value.

map $status $is_error {    
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default 0;
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main;

Com essa configuração, passamos a variável $status por um bloco map para determinar o valor da variável $is_error, que é então avaliada pelo parâmetro access_log da diretiva if. Quando $is_error é avaliada como 1, gravamos uma entrada de log especial no arquivo access_debug.log.

No entanto, essa configuração não detecta erros encontrados durante o processamento da solicitação que acabam sendo resolvidos e, portanto, resultam no status 200 OK. Um exemplo disso ocorre quando o NGINX faz o balanceamento de carga entre vários servidores upstream. Se ocorrer um erro com o servidor selecionado, o NGINX encaminhará a solicitação ao próximo servidor, de acordo com as condições configuradas pela diretiva proxy_next_upstream. Desde que um dos servidores upstream responda com sucesso, o cliente receberá uma resposta bem-sucedida, que será registrada com o status 200. No entanto, a experiência do usuário provavelmente será ruim devido às novas tentativas, e talvez não seja imediatamente evidente que um servidor upstream não está íntegro. Afinal, registramos um 200.

Quando o NGINX tenta encaminhar uma solicitação por proxy para vários servidores upstream, todos os endereços deles são registrados na variável $upstream_addr. O mesmo vale para outras variáveis $upstream_*, como, por exemplo, $upstream_status, que registra o código de resposta de cada servidor consultado. Portanto, quando vemos várias entradas nessas variáveis, sabemos que algo deu errado – provavelmente há um problema com pelo menos um dos servidores upstream.

Que tal também registrarmos no arquivo access_debug.log quando a solicitação tiver sido encaminhada por proxy para vários servidores upstream?

map $upstream_status $multi_upstreams {    
"~,"    1; # Has a comma
    default 0;
} 

map $status $is_error {
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default $multi_upstreams; # If we tried more than one upstream server
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main; # Regular logging

Aqui, usamos outro bloco map para produzir uma nova variável ($multi_upstreams), cujo valor depende da presença de uma vírgula (,) em $upstream_status. Uma vírgula significa que há mais de um código de status e, portanto, mais de um servidor upstream foi encontrado. Essa nova variável determina o valor de $is_error quando $status não corresponde a nenhum dos códigos de erro listados.

Neste ponto, temos nosso log de acesso regular e um arquivo especial chamado access_debug.log que contém as solicitações com erro, mas ainda não definimos o formato de log access_debug. Agora, vamos garantir que o arquivo access_debug.log contenha todos os dados necessários para nos ajudar a diagnosticar problemas.

Registro em JSON com JavaScript

Inserir dados de diagnóstico no access_debug.log não é difícil. O NGINX fornece mais de 100 variáveis relacionadas ao processamento HTTP, e podemos definir uma diretiva especial log_format que capture quantas delas forem necessárias. No entanto, criar um formato de log simplista para essa finalidade apresenta algumas desvantagens.

• É um formato personalizado – você precisa treinar um analisador de logs para interpretá-lo
• As entradas podem ser muito longas e difíceis de ler durante a solução de problemas em tempo real
• Você precisa consultar continuamente o formato do log para interpretar as entradas
• Não é possível registrar valores não determinísticos, como “todos os cabeçalhos da requisição”

Podemos enfrentar esses desafios gravando entradas de log em um formato estruturado, como JSON, usando o módulo JavaScript do NGINX<.htmla> (njs). O formato JSON também é amplamente compatível com sistemas de processamento de logs, como Splunk, LogStash, Graylog e Loggly. Ao transferir a sintaxe de log_format para uma função JavaScript, aproveitamos a sintaxe nativa do JSON, com acesso a todas as variáveis do NGINX e a dados adicionais do objeto ‘r’ do njs.

js_import conf.d/json_log.js;js_set $json_debug_log json_log.debugLog;

log_format access_debug escape=none $json_debug_log; # Offload to njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

A diretiva js_import especifica o arquivo que contém o código JavaScript e o importa como um módulo. O código pode ser encontrado aqui. Sempre que gravamos uma entrada no log de acesso que usa o formato de log access_debug, a variável $json_debug_log é avaliada. Essa variável é avaliada por meio da execução da função JavaScript debugLog, conforme definido pela diretiva js_set.

Essa combinação de código JavaScript e configuração do NGINX gera logs de diagnóstico como estes.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq{
   "timestamp": "2020-09-21T11:25:55+00:00",
   "connection": {
      "request_count": 1,
      "elapsed_time": 0.555,
      "pipelined": false,
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c",
         "session_reused": false,
         "client_cert": {
            "status": "NONE"
         }
      }
   },
   "request": {
      "client": "127.0.0.1",
      "port": 443,
      "host": "foo.example.com",
      "method": "GET",
      "uri": "/one",
      "http_version": 1.1,
      "bytes_received": 87,
      "headers": {
         "Host": "foo.example.com:443",
         "User-Agent": "curl/7.64.1",
         "Accept": "*/*"
      }
   },
   "upstreams": [
      {
         "server_addr": "10.37.0.71",
         "server_port": 443,
         "connect_time": null,
         "header_time": null,
         "response_time": 0.551,
         "bytes_sent": 0,
         "bytes_received": 0,
         "status": 504
      },
      {
         "server_addr": "10.37.0.72",
         "server_port": 443,
         "connect_time": 0.004,
         "header_time": 0.004,
         "response_time": 0.004,
         "bytes_sent": 92,
         "bytes_received": 4161,
         "status": 200
      }
   ],
   "response": {
      "status": 200,
      "bytes_sent": 186,
      "headers": {
         "Content-Type": "text/html",
         "Content-Length": "4161"
      }
   }
}

O formato JSON permite ter objetos separados para informações relacionadas à conexão HTTP como um todo (incluindo SSL/TLS), à solicitação, aos upstreams e à resposta. Observe como o primeiro upstream (10.37.0.71) retornou o status 504 (Gateway Timeout) antes que o NGINX tentasse o próximo upstream (10.37.0.72), que respondeu com sucesso. O tempo limite de meio segundo (indicado como response_time no primeiro elemento do objeto upstreams) é responsável pela maior parte da latência total dessa resposta bem-sucedida (indicada como elapsed_time no objeto connection).

Veja outro exemplo de uma entrada de log (truncada), referente a um erro de cliente causado por um certificado de cliente expirado.

{   
"timestamp": "2020-09-22T10:20:50+00:00",
   "connection": {
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
         "session_reused": false,
         "client_cert": {
            "status": "FAILED:certificate has expired",
            "serial": "1006",
            "fingerprint": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
            "subject": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
            "issuer": "CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US",
            "starts": "Sep 20 12:00:11 2019 GMT",
            "expires": "Sep 20 12:00:11 2020 GMT",
            "expired": true,
         ...
   "response": {
      "status": 400,
      "bytes_sent": 283,
      "headers": {
      "Content-Type": "text/html",
      "Content-Length": "215"
   }
}

Resumo

Ao gerar dados de diagnóstico detalhados somente quando encontramos um erro, possibilitamos a solução de problemas em tempo real sem a necessidade de realizar nenhuma reconfiguração. As solicitações bem-sucedidas não são afetadas, pois o código JavaScript é executado somente quando detectamos um erro na etapa de registro, depois que o último byte é enviado ao cliente.

A configuração completa está disponível no GitHub – que tal testá-la em seu ambiente? Se você ainda não usa o NGINX Plus, inicie hoje mesmo uma avaliação gratuita de 30 dias ou entre em contato conosco para conversar sobre seus casos de uso.

Sobre o autor

Liam CrillyDiretor Sênior de Gestão de Produtos

Mais publicações de Liam Crilly