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

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

Editor : este blog es uno de varios que tratan sobre el registro con NGINX y NGINX Plus. Ver también:

• Seguimiento de aplicação con NGINX y NGINX Plus
• Solicitudes de muestreo con registro condicional de NGINX

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

NGINX ayuda a organizaciones de todos los tamaños a ejecutar sus sitios web, aplicações y API de misión crítica. Independientemente de su escala y la elección de infraestructura de implementación, ejecutar en producción no es fácil. En este artículo hablamos de solo uno de los aspectos difíciles de una implementación de producción: el registro. Más específicamente, analizamos el equilibrio entre recopilar la cantidad adecuada de registros detallados para solucionar problemas sin verse inundado de datos innecesarios.

Conceptos básicos del registro

NGINX proporciona dos mecanismos de registro diferentes: registro de acceso para solicitudes de clientes y registro de errores cuando las cosas salen mal. Estos mecanismos están disponibles tanto en los módulos HTTP como en Stream (TCP/UDP), pero aquí nos centramos en el tráfico HTTP. (También hay un tercer mecanismo de registro que utiliza el nivel de gravedad de depuración , pero no lo analizaremos aquí).

Una configuración de registro NGINX típica y predeterminada se ve así.

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; # Registro con el formato 'main'
error_log /var/log/nginx/error.log warn; # Registro hasta el nivel de severidad 'warn'
...
}

La directiva log_format describe el contenido y la estructura de las entradas de registro creadas cuando se incluye la directiva access_log en la configuración. El ejemplo anterior es una extensió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 a registrar, pero no el contenido o el formato de las entradas, que son fijos. Más sobre esto en la siguiente sección.

Otros aspectos destacables del registro de NGINX incluyen:

• Las directivas de registro son heredadas automáticamente por los contextos de configuración de nivel inferior. Por ejemplo, una directiva access_log en el contexto http se aplica a todos los bloques server{} .
• Una directiva de registro en un contexto secundario anula las directivas heredadas.
• Pueden existir múltiples directivas de registro en el mismo contexto. Por ejemplo, se podrían usar dos directivas access_log para crear un archivo de registro CLF estándar y un segundo registro más detallado.

La realidad del registro en producción

En términos generales, queremos utilizar el registro de acceso para proporcionar análisis y estadísticas de uso, y utilizar el registro de errores para detectar fallas y solucionar problemas. Pero ejecutar un sistema de producción rara vez es tan sencillo. A continuación se presentan algunos desafíos comunes:

• Los registros de acceso carecen de suficientes detalles para la solución de problemas
• Los registros de errores revelan buenos detalles sobre el nivel de gravedad de la información , pero son demasiado detallados para las operaciones normales.
• El formato del registro de errores es fijo y, por lo tanto, no se puede personalizar para incluir variables de particular interés.
• Las entradas en el registro de errores no incluyen el contexto de la solicitud y son difíciles de hacer coincidir con la entrada del registro de acceso correspondiente.

Además, cambiar la configuración de NGINX para agregar 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 implementar la configuración. Completamente seguro, pero algo engorroso a la hora de solucionar un problema en vivo como, "¿por qué veo un pico en 4xx / 5“¿xx errores?”. Por supuesto, esto se magnifica cuando hay múltiples instancias de NGINX que manejan el mismo tráfico en un clúster.

Uso de un segundo registro de acceso para errores

Personalizar el formato del registro de acceso para enriquecer los datos recopilados para cada solicitud es un enfoque común para mejorar el análisis, pero no es adecuado para el diagnóstico o la resolución de problemas. Pedirle al registro de acceso principal que haga dos trabajos es una solución artificial, porque generalmente queremos mucha más información para la resolución de problemas que para el análisis regular. Agregar numerosas variables al registro de acceso principal puede aumentar drásticamente los volúmenes de registros con datos que solo son útiles ocasionalmente.

En lugar de ello, podemos utilizar un segundo registro de acceso y escribir en él sólo cuando encontremos un error que justifique la depuración. La directiva access_log admite el registro condicional con 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.

mapa $status $is_error { 400 1; # Solicitud incorrecta, incluido el certificado de cliente vencido 495 1; # Error de certificado de cliente 502 1; # Puerta de enlace incorrecta (no se pudo seleccionar ningún servidor ascendente) 504 1; # Tiempo de espera de la puerta de enlace (no se pudo conectar al servidor ascendente seleccionado) predeterminado 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;

Con esta configuración, pasamos la variable $status a través de un bloque de mapa para determinar el valor de la variable $is_error , que luego es evaluado por el parámetro if de la directiva access_log . Cuando $is_error se evalúa como1 Escribimos una entrada de registro especial en el archivo access_debug.log .

Sin embargo, esta configuración no detecta los errores encontrados durante el procesamiento de la solicitud que finalmente se resuelven y, por lo tanto, dan como resultado el estado200 DE ACUERDO . Un ejemplo de ello es cuando NGINX equilibra la carga entre múltiples servidores ascendentes. Si se encuentra un error con el servidor seleccionado, NGINX pasa la solicitud al siguiente servidor bajo las condiciones configuradas por la directiva proxy_next_upstream . Siempre que uno de los servidores ascendentes responda correctamente, el cliente recibirá una respuesta exitosa, que se registrará con el estado200 . Sin embargo, es probable que la experiencia del usuario sea deficiente debido a los reintentos y puede que no sea inmediatamente obvio que un servidor ascendente no funciona correctamente. Después de todo, hemos registrado un200 .

Cuando NGINX intenta conectarse a múltiples servidores ascendentes, todas sus direcciones se capturan en la variable $upstream_addr . Lo mismo se aplica a otras variables $upstream_* , por ejemplo, $upstream_status , que captura el código de respuesta de cada servidor intentado. Entonces, cuando vemos múltiples entradas en estas variables, sabemos que algo malo sucedió: probablemente tenemos un problema con al menos uno de los servidores ascendentes.

¿Qué tal si también escribimos en access_debug.log cuando la solicitud fue enviada a múltiples servidores ascendentes?

map $upstream_status $multi_upstreams { "~," 1; # Tiene una coma por defecto 0; } map $status $is_error { 400 1; # Solicitud incorrecta, incluyendo certificado de cliente caducado 495 1; # Error de certificado de cliente 502 1; # Puerta de enlace incorrecta (no se pudo seleccionar ningún servidor ascendente) 504 1; # Tiempo de espera de la puerta de enlace (no se pudo conectar al servidor ascendente seleccionado) por defecto $multi_upstreams; # Si probamos más de un servidor ascendente } 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

Aquí usamos otro bloque de mapa para producir una nueva variable ( $multi_upstreams ) cuyo valor depende de la presencia de una coma ( , ) en $upstream_status . Una coma significa que hay más de un código de estado y, por lo tanto, se encontró más de un servidor ascendente. Esta nueva variable determina el valor de $is_error cuando $status no es uno de los códigos de error enumerados.

En este punto tenemos nuestro registro de acceso regular y un archivo especial access_debug.log que contiene solicitudes erróneas, pero aún no hemos definido el formato del registro access_debug.log . Ahora asegurémonos de que tenemos todos los datos que necesitamos en el archivo access_debug.log para ayudarnos a diagnosticar problemas.

Registro JSON con JavaScript

Obtener 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 de ellas como necesitemos. Sin embargo, existen algunas desventajas en la creación de un formato de registro ingenuo para este propósito.

• Es un formato personalizado: debes entrenar a un analizador de registros para que sepa cómo leerlo.
• Las entradas pueden ser muy largas y difíciles de leer para los humanos durante la resolución de problemas en vivo.
• Es necesario consultar continuamente el formato de registro para interpretar las entradas.
• No es posible registrar valores no deterministas como “todos los encabezados de solicitud”.

Podemos abordar estos desafíos escribiendo entradas de registro en un formato estructurado como JSON, utilizando el módulo JavaScript NGINX<.htmla> (njs). El formato JSON también es ampliamente compatible con sistemas de procesamiento de registros como Splunk , LogStash , Graylog y Loggly . Al descargar la sintaxis log_format a una función de JavaScript, nos beneficiamos de la sintaxis JSON nativa, con acceso a todas las variables NGINX y 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; # Descargar a 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 un módulo. El código en sí se puede encontrar aquí . Siempre que escribimos una entrada de 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 JavaScript debugLog según lo define la directiva js_set .

Esta combinación de código JavaScript y configuración NGINX produce registros de diagnóstico que se ven así.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq { "marca de tiempo": "2020-09-21T11:25:55+00:00", "conexión": { "número_de_solicitudes": 1, "tiempo transcurrido": 0.555, "pipelined": falso, "ssl": { "protocolo": "TLSv1.2", "cifrado": "ECDHE-RSA-AES256-GCM-SHA384", "id_de_sesión": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c", "sesión_reutilizada": falso, "certificado_de_cliente": { "estado": "NINGUNO" } } }, "solicitud": { "cliente": "127.0.0.1", "puerto": 443, "host": "foo.example.com", "método": "GET", "uri": "/uno", "http_version": 1.1, "bytes_recibidos": 87, "encabezados": { "Host": "foo.example.com:443", "Agente de usuario": "curl/7.64.1", "Aceptar": "*/*" } }, "subidas": [ { "dirección_del_servidor": "10.37.0.71", "puerto_del_servidor": 443, "tiempo_de_conexión": nulo, "tiempo_de_encabezado": nulo, "tiempo_de_respuesta": 0.551, "bytes_enviados": 0, "bytes_recibidos": 0, "estado": 504 }, { "dirección_del_servidor": "10.37.0.72", "puerto_del_servidor": 443, "tiempo_de_conexión": 0.004, "tiempo de encabezado": 0.004, "tiempo_de_respuesta": 0.004, "bytes_enviados": 92, "bytes_recibidos": 4161, "estado": 200 } ], "respuesta": { "estado": 200, "bytes_enviados": 186, "encabezados": { "Tipo de contenido": "texto/html", "Longitud del contenido": "4161" } } }

El formato JSON nos permite tener objetos separados para la información relacionada con la conexión HTTP general (incluido SSL/TLS), la solicitud, los flujos ascendentes y la respuesta. Observe cómo el primer upstream (10.37.0.71) devolvió el estado 504( Tiempo de espera de puerta de enlace) antes de que NGINX intentara el siguiente upstream (10.37.0.72), que respondió con éxito. El tiempo de espera de medio segundo (reportado como response_time en el primer elemento del objeto upstreams ) representa la mayor parte de la latencia general para esta respuesta exitosa (reportada como elapsed_time en el objeto de conexión ).

A continuación se muestra otro ejemplo de una entrada de registro (truncada) para un error de cliente causado por un certificado de cliente vencido.

{ 
"marca de tiempo": "2020-09-22T10:20:50+00:00",
"conexión": {
"ssl": {
"protocolo": "TLSv1.2",
"cifrado": "ECDHE-RSA-AES256-GCM-SHA384",
"id_de_sesión": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
"sesión_reutilizada": falso,
"certificado_de_cliente": {
"estado": "FALLÓ: el certificado ha expirado",
"serie": "1006",
"huella dactilar": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
"asunto": "dirección de correo electrónico=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
"emisor": "CN=Demo CA Intermedia,OU=Demo CA,O=nginx,ST=CA,C=US",
"inicia": "20 de septiembre de 2019, 12:00:11 GMT", "caduca": "20 de septiembre 12:00:11 2020 GMT",
"expired": true,
...
"response": {
"status": 400,
"bytes_enviados": 283,
"encabezados": {
"Tipo de contenido": "texto/html",
"Longitud del contenido": "215"

resumen

Al generar datos de diagnóstico enriquecidos solo cuando encontramos un error, permitimos la resolución de problemas en tiempo real sin necesidad de realizar ninguna reconfiguración. Las solicitudes exitosas no se ven afectadas porque el código JavaScript se ejecuta solo cuando detectamos un error en la fase de registro, después de que se envía el último byte al cliente.

La configuración completa está disponible en GitHub : ¿por qué no probarla en tu entorno? Si aún no utiliza NGINX Plus, comience hoy mismo una prueba gratuita de 30 días o contáctenos para analizar sus casos de uso .