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

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

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

• Rastreamento de aplicativos com NGINX e NGINX Plus
• Solicitações de amostragem com registro condicional NGINX

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

O NGINX ajuda organizações de todos os tamanhos a executar seus sites, aplicativos e APIs de missão crítica. Independentemente da sua escala e escolha de infraestrutura de implantação, executar em produção não é fácil. Neste artigo, falamos sobre apenas uma das coisas difíceis sobre uma implantação de produção: o registro. Mais especificamente, discutimos o ato de equilíbrio de coletar a quantidade certa de logs detalhados para solução de problemas sem ser inundado com dados desnecessários.

Noções básicas de registro

O NGINX fornece dois mecanismos de registro diferentes: 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 gravidade de depuração , mas não o discutiremos aqui.)

Uma configuração de registro padrão típica do NGINX se parece com 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; # Registre usando o formato 'main'
error_log /var/log/nginx/error.log warn; # Registre até o nível de gravidade 'warn'
...
}

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 gravidade das mensagens a serem registradas, mas não o conteúdo ou o formato das entradas, que são fixos. Mais sobre isso na próxima seção.

Outros aspectos dignos de nota do registro 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 diretivas herdadas.
• Várias diretivas de registro podem existir no mesmo contexto. Por exemplo, duas diretivas access_log podem ser usadas para criar um arquivo de log CLF padrão e um segundo log mais detalhado.

A realidade do registro na produção

Em termos gerais, queremos usar o log de acesso para fornecer análises e estatísticas de uso, e usar o log de erros para detecção de falhas e solução de problemas. Mas executar um sistema de produção raramente é tão simples. Aqui estão alguns desafios comuns:

• Os registros de acesso não possuem detalhes suficientes para solução de problemas
• Os logs de erros revelam bons detalhes no nível de gravidade das informações , mas são muito prolixos para operações normais
• O formato do log de erros é fixo e, portanto, não pode ser personalizado para incluir variáveis de interesse particular
• As entradas no log de erros não incluem o contexto da solicitação e são difíceis de corresponder à entrada do log de acesso correspondente

Além disso, alterar a configuração do NGINX para adicionar ou remover detalhes de registro em um ambiente de produção também pode exigir passar por um processo de controle de alterações e reimplantar a configuração. Totalmente seguro, mas um tanto complicado ao solucionar um problema ativo, como "por que estou vendo um pico em 4xx / 5xx erros?”. É claro que isso é ampliado quando há várias instâncias do NGINX manipulando 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 para cada solicitação é uma abordagem comum para análises aprimoradas, mas não é bem dimensionável para diagnósticos ou solução de problemas. Solicitar que o log de acesso principal execute duas tarefas é uma solução artificial, porque normalmente queremos muito mais informações para solução de problemas do que para análises regulares. Adicionar diversas variáveis ao log de acesso principal pode aumentar drasticamente os volumes de log com dados que são úteis apenas ocasionalmente.

Em vez disso, podemos usar um segundo log de acesso e escrever nele somente quando encontrarmos um erro que justifique depuração. A diretiva access_log oferece suporte ao registro condicional com o parâmetro if – as solicitações são registradas somente quando a variável especificada é avaliada como um valor diferente de zero e não vazio.

map $status $is_error { 400 1; # Solicitação inválida, incluindo certificado de cliente expirado 495 1; # Erro de certificado de cliente 502 1; # Gateway inválido (nenhum servidor upstream pôde ser selecionado) 504 1; # Tempo limite do gateway (não foi possível conectar ao upstream selecionado) padrão 0; } access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Registro de diagnóstico access_log /var/log/nginx/access.log main;

Com essa configuração, passamos a variável $status por um bloco de mapa para determinar o valor da variável $is_error , que é então avaliada pelo parâmetro if da diretiva access_log . Quando $is_error é avaliado como1 escrevemos 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 são finalmente resolvidos e, portanto, resultam em status200 OK . Um exemplo disso é quando o NGINX está fazendo balanceamento de carga entre vários servidores upstream. Se um erro for encontrado no servidor selecionado, o NGINX passará a solicitação para o próximo servidor sob 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 status200 . No entanto, a experiência do usuário provavelmente será ruim devido às tentativas, e pode não ficar imediatamente óbvio que um servidor upstream não está íntegro. Afinal, registramos um200 .

Quando o NGINX tenta fazer proxy para vários servidores upstream, todos os seus endereços são capturados na variável $upstream_addr . O mesmo vale para outras variáveis $upstream_* , por exemplo $upstream_status que captura o código de resposta de cada servidor tentado. Então, quando vemos várias entradas nessas variáveis, sabemos que algo ruim aconteceu – provavelmente temos um problema com pelo menos um dos servidores upstream.

Que tal também escrevermos em access_debug.log quando a solicitação foi enviada por proxy para vários servidores upstream?

map $upstream_status $multi_upstreams { "~," 1; # Tem uma vírgula padrão 0; } map $status $is_error { 400 1; # Solicitação inválida, incluindo certificado de cliente expirado 495 1; # Erro de certificado de cliente 502 1; # Gateway inválido (nenhum servidor upstream pôde ser selecionado) 504 1; # Tempo limite do gateway (não foi possível conectar ao upstream selecionado) padrão $multi_upstreams; # Se tentarmos mais de um servidor upstream } access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Registro de diagnóstico access_log /var/log/nginx/access.log main; # Registro regular

Aqui usamos outro bloco de mapa 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. Esta nova variável determina o valor de $is_error quando $status não é um dos códigos de erro listados.

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

Registro JSON com JavaScript

Obter dados de diagnóstico em access_debug.log não é difícil. O NGINX fornece mais de 100 variáveis relacionadas ao processamento HTTP, e podemos definir uma diretiva log_format especial que captura quantas delas precisarmos. No entanto, há algumas desvantagens em criar um formato de log simples para essa finalidade.

• É um formato personalizado – você precisa treinar um analisador de log para lê-lo
• As entradas podem ser muito longas e difíceis de ler para humanos durante a solução de problemas ao vivo
• 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 de solicitação”

Podemos resolver esses desafios escrevendo entradas de log em um formato estruturado, como JSON, usando o módulo NGINX JavaScript<.htmla> (njs). O formato JSON também é amplamente suportado por sistemas de processamento de logs, como Splunk , LogStash , Graylog e Loggly . Ao descarregar a sintaxe log_format para uma função JavaScript, nos beneficiamos da sintaxe JSON nativa, com acesso a todas as variáveis NGINX e dados adicionais do objeto njs ' r ' .

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

log_format access_debug escape=none $json_debug_log; # Descarregar para 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 em si pode ser encontrado aqui . Sempre que escrevemos uma entrada de log de acesso que usa o formato de log access_debug , a variável $json_debug_log é avaliada. Esta variável é avaliada executando a função JavaScript debugLog, conforme definido pela diretiva js_set .

Essa combinação de código JavaScript e configuração NGINX produz logs de diagnóstico semelhantes a este.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq { "carimbo de data/hora": "2020-09-21T11:25:55+00:00", "conexão": { "request_count": 1, "tempo_decorrido": 0,555, "pipelined": falso, "ssl": { "protocolo": "TLSv1.2", "cifra": "ECDHE-RSA-AES256-GCM-SHA384", "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c", "session_reused": falso, "client_cert": { "status": "NENHUM" } } }, "solicitação": { "cliente": "127.0.0.1", "porta": 443, "host": "foo.example.com", "método": "OBTER", "uri": "/um", "http_version": 1.1, "bytes_recebidos": 87, "cabeçalhos": { "Host": "foo.example.com:443", "Agente do usuário": "curl/7.64.1", "Aceitar": "*/*" } }, "upstreams": [ { "server_addr": "10.37.0.71", "porta_do_servidor": 443, "tempo_de_conexão": nulo, "tempo_de_cabeçalho": nulo, "tempo_de_resposta": 0,551, "bytes_enviados": 0, "bytes_recebidos": 0, "estado": 504 }, { "endereço_do_servidor": "10.37.0.72", "porta_do_servidor": 443, "tempo_de_conexão": 0,004, "header_time": 0,004, "tempo_de_resposta": 0,004, "bytes_enviados": 92, "bytes_recebidos": 4161, "estado": 200 } ], "resposta": { "status": 200, "bytes_enviados": 186, "cabeçalhos": { "Tipo de conteúdo": "texto/html", "Comprimento do conteúdo": "4161" } } }

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

Aqui está outro exemplo de uma entrada de log (truncada), para um erro de cliente causado por um certificado de cliente expirado.

{ 
"carimbo de data/hora": "2020-09-22T10:20:50+00:00",
"conexão": {
"ssl": {
"protocolo": "TLSv1.2",
"cifra": "ECDHE-RSA-AES256-GCM-SHA384",
"session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
"session_reused": falso,
"client_cert": {
"status": "FALHOU:certificado expirou",
"serial": "1006",
"impressão digital": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
"assunto": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
"emissor": "CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US",
"inicia": "20 de setembro 12:00:11 2019 GMT",
"expira": "20 de set. 12:00:11 2020 GMT",
"expired": true,
...
"response": {
"status": 400,
"bytes_enviados": 283,
"cabeçalhos": {
"Tipo de conteúdo": "texto/html",
"Comprimento do conteúdo": "215"
}
}

Resumo

Ao gerar dados de diagnóstico avançados somente quando encontramos um erro, possibilitamos a solução de problemas em tempo real sem a necessidade de realizar nenhuma reconfiguração. Solicitações bem-sucedidas não são afetadas porque o código JavaScript é executado somente quando detectamos um erro na fase de registro, após o último byte ter sido enviado ao cliente.

A configuração completa está disponível no GitHub – por que não experimentá-la em seu ambiente? Se você ainda não estiver executando o NGINX Plus, comece hoje mesmo um teste gratuito de 30 dias ou entre em contato conosco para discutir seus casos de uso .