Registro de diagnóstico con el módulo JavaScript de NGINX

NGINX | 29 de septiembre de 2020

Liam CrillyDirector sénior de Gestión de Producto

Resolución de problemas en producción sin ajustar el registro de errores

Editor – Este blog es uno de los varios que tratan sobre el registro con NGINX y NGINX Plus. Consulte también:

También es uno de los muchos blogs sobre casos de uso del módulo JavaScript de NGINX. Para consultar la lista completa, consulte «Casos de uso del módulo JavaScript de NGINX».

NGINX ayuda a organizaciones de todos los tamaños a mantener en funcionamiento sus sitios web, aplicaciones y API esenciales. Independientemente de su tamaño y de la infraestructura de despliegue que elijan, operar en producción no es fácil. En este artículo abordamos solo uno de los aspectos más complejos de un despliegue en producción: el registro de eventos. Más concretamente, analizamos cómo lograr el equilibrio entre recopilar suficientes registros detallados para solucionar problemas y evitar verse desbordado por datos innecesarios.

Conceptos básicos del registro

NGINX ofrece dos mecanismos de registro diferentes: el registro de acceso para las solicitudes de los clientes y el registro de errores para cuando algo sale mal. Estos mecanismos están disponibles tanto en el módulo HTTP como en el módulo Stream (TCP/UDP), pero aquí nos centraremos en el tráfico HTTP. (También existe un tercer mecanismo de registro que utiliza el nivel de gravedad de depuración, pero no lo abordaremos aquí).

Una configuración de registro predeterminada típica de NGINX tiene este aspecto.

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
    ...
}

La directiva log_format describe el contenido y la estructura de las entradas de registro que se crean cuando la directiva access_log se incluye en la configuración. El ejemplo anterior es una ampliación del formato de registro común (CLF) utilizado por muchos servidores web. Con la directiva error_log, se especifica el nivel de gravedad de los mensajes que se registrarán, pero no el contenido ni el formato de las entradas, que son fijos. Se ofrece más información al respecto en la siguiente sección.

Otros aspectos destacables del registro de NGINX son:

Las directivas de registro se heredan automáticamente en los contextos de configuración de nivel inferior. Por ejemplo, una directiva «access_log» del contexto «http» se aplica a todos los bloques «server{}».
Una directiva de registro en un contexto secundario prevalece sobre las directivas heredadas.
En un mismo contexto pueden existir varias directivas de registro. Por ejemplo, se podrían utilizar dos directivas access_log para crear tanto un archivo de registro CLF estándar como otro registro más detallado.

La realidad del registro en producción

En términos generales, queremos utilizar el registro de acceso para obtener datos analíticos y estadísticas de uso, y el registro de errores para detectar fallos y solucionar problemas. Sin embargo, gestionar un sistema en producción rara vez es tan sencillo. Estos son algunos de los retos más habituales:

Los registros de acceso no contienen suficiente información para solucionar problemas
Los registros de errores proporcionan un buen nivel de detalle con el nivel de gravedad info, pero resultan demasiado detallados para las operaciones habituales
El formato del registro de errores es fijo, por lo que no se puede personalizar para incluir variables de especial interés
Las entradas del registro de errores no incluyen el contexto de la solicitud y son difíciles de relacionar con la entrada correspondiente del registro de acceso

Además, cambiar la configuración de NGINX para añadir o eliminar detalles de registro en un entorno de producción también puede requerir pasar por un proceso de control de cambios y volver a desplegar la configuración. Es totalmente seguro, pero algo engorroso a la hora de diagnosticar un problema en tiempo real, como «¿por qué estoy observando un aumento repentino de los errores 4xx/5xx?». Esto se complica aún más cuando hay varias instancias de NGINX gestionando el mismo tráfico en un clúster.

Uso de un segundo registro de acceso para los errores

Personalizar el formato del registro de acceso para enriquecer los datos recopilados en cada solicitud es una práctica habitual para mejorar el análisis, pero no resulta escalable para el diagnóstico o la resolución de problemas. Hacer que el registro de acceso principal cumpla dos funciones es una solución forzada, ya que normalmente necesitamos mucha más información para resolver problemas que para los análisis habituales. Añadir numerosas variables al registro de acceso principal puede aumentar drásticamente el volumen de los registros con datos que solo resultan útiles de forma ocasional.

En su lugar, podemos utilizar un segundo registro de acceso y escribir en él únicamente cuando se produzca un error que requiera depuración. La directiva access_log admite el registro condicional mediante el parámetro if: las solicitudes solo se registran cuando la variable especificada se evalúa como un valor distinto de cero y no vacío.

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;

Con esta configuración, pasamos la variable $status por un bloque map para determinar el valor de la variable $is_error, que después se evalúa mediante el parámetro access_log de la directiva if. Cuando $is_error se evalúa como 1, escribimos una entrada de registro especial en el archivo access_debug.log.

Sin embargo, esta configuración no detecta los errores que se producen durante el procesamiento de las solicitudes y que finalmente se resuelven, por lo que dan lugar al estado 200 OK. Un ejemplo de ello se da cuando NGINX distribuye la carga entre varios servidores ascendentes. Si se produce un error con el servidor seleccionado, NGINX pasa la solicitud al siguiente servidor según las condiciones configuradas mediante la directiva proxy_next_upstream. Siempre que uno de los servidores ascendentes responda correctamente, el cliente recibirá una respuesta satisfactoria, que se registrará con el estado 200. Sin embargo, es probable que la experiencia del usuario sea deficiente debido a los reintentos, y puede que no resulte evidente de inmediato que un servidor ascendente no funciona correctamente. Al fin y al cabo, hemos registrado un 200.

Cuando NGINX intenta redirigir mediante proxy a varios servidores ascendentes, todas sus direcciones se registran en la variable $upstream_addr. Lo mismo ocurre con otras variables $upstream_*, por ejemplo, $upstream_status, que registra el código de respuesta de cada servidor con el que se ha intentado establecer conexión. Por tanto, cuando vemos varias entradas en estas variables, sabemos que algo ha ido mal: probablemente haya un problema con al menos uno de los servidores ascendentes.

¿Qué tal si también escribimos en access_debug.log cuando la solicitud se haya redirigido mediante proxy a varios servidores ascendentes?

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

Aquí usamos otro bloque map para generar una nueva variable ($multi_upstreams) cuyo valor depende de la presencia de una coma (,) en $upstream_status. Una coma indica que hay más de un código de estado y, por tanto, que se ha encontrado más de un servidor ascendente. Esta nueva variable determina el valor de $is_error cuando $status no coincide con ninguno de los códigos de error indicados.

Llegados a este punto, tenemos nuestro registro de acceso habitual y un archivo especial llamado access_debug.log que contiene las solicitudes con errores, pero aún no hemos definido el formato de registro access_debug. Asegurémonos ahora de que el archivo access_debug.log contenga todos los datos necesarios para ayudarnos a diagnosticar problemas.

Registro en formato JSON con JavaScript

Introducir datos de diagnóstico en access_debug.log no es difícil. NGINX proporciona más de 100 variables relacionadas con el procesamiento HTTP, y podemos definir una directiva log_format especial que capture tantas como necesitemos. Sin embargo, crear un formato de registro básico para este fin presenta algunos inconvenientes.

Es un formato personalizado: hay que enseñar al analizador de registros a interpretarlo
Las entradas pueden ser muy largas y difíciles de leer durante la resolución de problemas en tiempo real
Es necesario consultar continuamente el formato del registro para poder interpretar las entradas
No es posible registrar valores no deterministas, como «todas las cabeceras de la solicitud»

Podemos abordar estos retos escribiendo las entradas de registro en un formato estructurado como JSON mediante el módulo JavaScript de NGINX<.htmla> (njs). El formato JSON también es ampliamente compatible con sistemas de procesamiento de registros como Splunk, LogStash, Graylog y Loggly. Al trasladar la sintaxis de log_format a una función de JavaScript, aprovechamos la sintaxis nativa de JSON y podemos acceder a todas las variables de NGINX y a datos adicionales del objeto «r» de 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;

La directiva js_import especifica el archivo que contiene el código JavaScript y lo importa como módulo. El código se puede consultar aquí. Cada vez que escribimos una entrada en el registro de acceso que utiliza el formato de registro access_debug, se evalúa la variable $json_debug_log. Esta variable se evalúa ejecutando la función de JavaScript debugLog, tal como se define mediante la directiva js_set.

Esta combinación de código JavaScript y configuración de NGINX genera registros de diagnóstico como los siguientes.

$ 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"
      }
   }
}

El formato JSON nos permite disponer de objetos independientes para la información relacionada con la conexión HTTP general (incluido SSL/TLS), la solicitud, los servidores upstream y la respuesta. Observe cómo el primer servidor upstream (10.37.0.71) devolvió el estado 504 (Gateway Timeout) antes de que NGINX probara el siguiente servidor upstream (10.37.0.72), que respondió correctamente. El tiempo de espera de medio segundo (indicado como response_time en el primer elemento del objeto upstreams) representa la mayor parte de la latencia total de esta respuesta satisfactoria (indicada como elapsed_time en el objeto connection).

Este es otro ejemplo de una entrada de registro (truncada), correspondiente a un error de cliente causado por un certificado de cliente caducado.

{   
"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"
   }
}

Resumen

Al generar datos de diagnóstico detallados únicamente cuando se produce un error, permitimos solucionar problemas en tiempo real sin necesidad de realizar ninguna reconfiguración. Las solicitudes procesadas correctamente no se ven afectadas, ya que el código JavaScript solo se ejecuta cuando detectamos un error durante la fase de registro, después de haber enviado el último byte al cliente.

La configuración completa está disponible en GitHub; ¿por qué no la prueba en su entorno? Si aún no utiliza NGINX Plus, inicie hoy mismo una prueba gratuita de 30 días o póngase en contacto con nosotros para hablar sobre sus casos de uso.