使用NGINX JavaScript Module进行诊断日志记录

NGINX | 2020年9月29日

无需调整错误日志即可在生产环境中进行故障排除

编者：本博客是探讨NGINX和NGINX Plus的日志记录的系列博客之一。另请参阅：

这也是介绍NGINX JavaScript模块用例的众多博客文章之一。有关完整列表，请参阅《NGINX JavaScript模块用例》。

NGINX可帮助各种规模的组织运行其关键任务网站、应用和API。无论组织规模如何，也无论选择何种部署基础设施，生产环境中的运行都并非易事。本文将探讨生产部署中的一项难题：日志记录。具体而言，我们将讨论如何在收集适量的详细日志以便排查问题与避免被不必要的数据淹没之间取得平衡。

日志记录基础

NGINX提供两种不同的日志记录机制：访问日志记录用于记录客户端请求，错误日志记录用于记录发生的问题。这些机制在HTTP和Stream（TCP/UDP）模块中均可用，但本文重点介绍HTTP流量。（此外，还有第三种日志记录机制，它使用调试严重性级别，但本文不作讨论。）

典型的NGINX默认日志配置如下所示。

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

当配置中包含log_format指令时，该指令用于描述access_log指令所创建日志条目的内容和结构。上述示例扩展了许多Web服务器使用的通用日志格式（CLF）。使用error_log指令时，可以指定要记录的消息严重性级别，但不能指定日志条目的内容或格式，因为二者是固定的。下一节将对此进行详细介绍。

NGINX日志记录还包括以下值得注意的方面：

日志记录指令会自动由较低级别的配置上下文继承。例如，在access_log指令位于http上下文时，会应用于所有server{}块。
子上下文中的日志记录指令会覆盖继承的指令。
同一上下文中可以存在多个日志记录指令。例如，可以使用两个access_log指令，分别创建一个标准CLF日志文件和另一个更详细的日志文件。

生产环境中的日志记录现状

一般来说，我们希望使用访问日志进行分析并提供使用情况统计信息，使用错误日志检测故障并排查问题。但生产系统的运行往往没有这么简单。以下是一些常见挑战：

访问日志缺少故障排除所需的详细信息
错误日志在info严重性级别下会提供较为详细的信息，但对于正常运行而言过于冗长
错误日志格式固定，因此无法通过自定义来包含特别关注的变量
错误日志条目不包含请求上下文，因此难以与相应的访问日志条目匹配

此外，在生产环境中更改NGINX配置以增加或减少日志详细信息，可能还需要经过变更控制流程并重新部署配置。这样做完全安全，但在排查实时问题时会有些繁琐，例如：“为什么4xx/5xx错误突然激增？”如果集群中有多个NGINX实例处理相同的流量，问题自然会更加突出。

使用第二个访问日志记录错误

自定义访问日志格式，以丰富为每个请求收集的数据，是增强分析的常见方法，但难以扩展用于诊断或故障排除。让主访问日志同时承担两项任务并不合理，因为故障排除通常需要比常规分析多得多的信息。在主访问日志中添加大量变量，可能会显著增加日志量，而其中的数据仅偶尔有用。

可以改用第二个访问日志，仅在遇到需要调试的错误时才写入该日志。access_log指令通过if参数支持条件日志记录；仅当指定变量的计算结果为非零且非空值时，才会记录请求。

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;

使用此配置时，我们将$status变量传入map块，以确定$is_error变量的值。随后，access_log指令的if参数会对该值进行求值。当$is_error的求值结果为1时，我们会向access_debug.log文件写入一条特殊日志记录。

但是，此配置无法检测在请求处理期间遇到但最终得到解决的错误，因此最终状态为200 OK。例如，NGINX在多个上游服务器之间进行负载均衡时，就可能出现这种情况。如果选定的服务器发生错误，NGINX会根据proxy_next_upstream指令配置的条件，将请求传递给下一台服务器。只要其中一台上游服务器成功响应，客户端就会收到成功响应，并以状态200记录到日志中。但是，由于发生了重试，用户体验可能较差，而且可能无法立即发现某台上游服务器运行异常。毕竟，日志中记录的是200。

当NGINX尝试将请求代理到多个上游服务器时，所有这些服务器的地址都会记录在$upstream_addr变量中。其他$upstream_*变量也是如此。例如，$upstream_status会记录每次尝试连接的服务器所返回的响应代码。因此，如果这些变量中出现多个条目，就说明发生了异常，很可能至少有一台上游服务器存在问题。

如果请求被代理到多个上游服务器，是否也可以将相关信息写入access_debug.log？

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

这里使用另一个map块生成新变量（$multi_upstreams），其值取决于$upstream_status中是否存在逗号（,）。逗号表示存在多个状态码，因此请求经过了多个上游服务器。当$status不是列出的错误代码之一时，这个新变量将决定$is_error的值。

此时，我们已有常规访问日志，以及一个专门记录错误请求的access_debug.log文件，但尚未定义access_debug日志格式。现在，我们需要确保access_debug.log文件包含诊断问题所需的全部数据。

使用JavaScript记录JSON日志

将诊断数据写入access_debug.log并不困难。NGINX提供了100多个变量，这些变量与HTTP处理相关。我们还可以定义一个专用的log_format指令，按需捕获其中任意数量的变量。不过，为此构建一个简单粗略的日志格式也存在一些缺点。

这是自定义格式，需要训练日志解析器才能读取
条目可能很长，人工在实时故障排查过程中难以阅读
需要不断参照日志格式才能解读日志条目
无法记录“所有请求标头”等非确定性值

我们可以使用NGINX JavaScript module<.htmla> (njs)，以JSON等结构化格式写入日志条目，从而应对这些挑战。JSON格式也受到以下日志处理系统的广泛支持：Splunk、LogStash、Graylog和Loggly。将log_format语法交由JavaScript函数处理后，便可利用原生JSON语法，访问所有NGINX变量以及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; # Offload to njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

The js_import指令指定包含JavaScript代码的文件，并将其作为模块导入。代码可在此处查看。每当写入使用access_debug日志格式的访问日志条目时，系统都会对$json_debug_log变量求值。求值方式是执行由debugLog JavaScript函数，该函数通过js_set指令定义。

这种JavaScript代码与NGINX配置的组合会生成如下所示的诊断日志。

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

JSON格式支持使用单独的对象来记录与整个HTTP连接（包括SSL/TLS）、请求、上游和响应相关的信息。请注意，第一个上游（10.37.0.71）返回了状态码504（网关 超时），随后NGINX尝试了下一个上游（10.37.0.72），并成功获得响应。此次半秒超时（在upstreams对象的第一个元素中报告为response_time）占该成功响应总延迟的大部分（在connection对象中报告为elapsed_time）。

以下是另一个（已截断的）日志条目示例，其中的客户端错误由客户端证书过期导致。

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