原文作者：Liam Crilly of F5

原文链接：使用 NGINX JavaScript 模块进行诊断日志记录

转载来源：NGINX 官方网站

在不调整错误日志的情况下，在生产环境中进行故障排除

还有多篇讨论 NGINX 和 NGINX Plus日志记录的文章，本文只是其中之一。另请参阅：

• NGINX 和 NGINX Plus 的应用跟踪
• NGINX 条件日志记录的日志采集请求

本文也是有关 NGINX JavaScript 模块用例的博文之一。相关文章的完整列表，请参阅《借助 NGINX JavaScript 模块，充分利用 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 日志记录的其他重要方面：

• 日志记录指令将由低级配置上下文自动继承。举例来说，http上下文中的access_log指令应用于所有server{}代码块。
• 子上下文中的日志记录指令会重写继承的指令。
• 在同一上下文中可能存在多个日志记录指令。举例来说，可能会使用两个access_log指令来创建标准 CLF 日志文件以及更详细的日志。

生产环境中的日志记录

一般而言，我们希望使用访问日志来提供分析和使用情况的信息，使用错误日志进行故障检测和排除。但在实际的生产系统运行中，情况可能没那么简单。下面就介绍下一些常见的挑战：

• 访问日志无法为故障排除提供足够的信息。
• 错误日志能够在info严重性级别提供充分的详情，但这些详情对于常规操作来说太过繁琐。
• 错误日志格式是固定的，无法进行自定义以包含特定目的的变量。
• 错误日志中的条目不包含请求的上下文，难以与相应的访问日志条目相匹配。

此外，要想更改 NGINX 配置以在生产环境中添加或删除日志记录详情，可能也要遵循变更控制流程，并重新部署配置。当解决实际问题时，例如“为什么会在4_xx_/5_xx_错误中看到一个激增？”，虽然完全安全但略显繁琐。当有多个 NGINX 实例在集群中处理相同的流量时，会更繁琐。

使用第二个访问日志处理错误

对访问日志的格式进行自定义以丰富针对每项请求所收集的数据是一种常见的分析增强方法，但不是很适合诊断或故障排除。要求主访问日志同时胜任这两项作业实为牵强之举，因为与常规分析相比，故障排除通常需要更多的信息。如果为主访问日志添加大量变量，则会显著增加日志文件的大小，但其中的数据却只是偶尔才会用到。

为了解决这一难题，我们只在遇到需要调试的错误时，才使用第二个访问日志并写入其中。access_log指令使用if参数，支持条件日志记录——仅当指定变量被估值为非零值（非空值）时，才将请求记录在内。

map $status $is_error {
    400     1; # 请求出错，客户端证书已出错
    495     1; # 客户端证书出错
    502     1; # 错误网关（没有可选的上游服务器）
    504     1; # 网关超时（无法连接到选定上游服务器）
    default 0;
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # 诊断日志记录
access_log/var/log/nginx/access.log main;

借助该配置，我们可通过map代码块传递$status变量，以确定$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; # 有一个逗号
    default 0;
} 

map $status $is_error {
    400     1; # 请求出错，客户端证书已出错
    495     1; # 客户端证书出错
    502     1; # 错误网关（没有可选的上游服务器）
    504     1; # 网关超时（无法连接到选定上游服务器）
    default $multi_upstreams; # 如果我们尝试超过一台上游服务器
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # 诊断日志记录
access_log /var/log/nginx/access.log main; # 常规日志

在这里我们使用另一个map代码块来生成新变量 ($multi_upstreams)，变量值取决于$upstream_status中是否存在逗号 (,)。逗号意味着存在多个状态代码，遇到了多台上游服务器。当$status不是上述任何错误代码时，这个新变量决定$is_error的值。

到这里，我们已经介绍了常规访问日志和包含错误请求的特殊access_debug.log文件，但尚未定义access_debug日志格式。下面就了解下如何获取access_debug.log文件所需的数据，以帮助我们诊断问题。

使用 JavaScript 进行 JSON 日志记录

将诊断数据记录到access_debug.log中并非难事。NGINX 提供了上百种与 HTTP 处理相关的变量，我们可以定义一种特殊的log_format指令以捕捉所需数量的条目。但是，这样定义原生日志格式也有一些弊端。

• 这是一种自定义格式，因此需要训练日志解析器来阅读这种格式
• 当进行实际故障排除时，条目可能很长，难以查找
• 需要不断参考日志格式才能理解条目
• 无法记录非确定值，例如“所有请求标头”

为了应对这些挑战，我们可以使用NGINX JavaScript module(njs) 以 JSON 等结构化格式写入日志条目。Splunk、LogStash、Graylog, 和Loggly等多种日志处理系统都支持 JSON 格式。通过将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;

js_import指令指定了包含 JavaScript 代码并将其作为模块导出的文件。可点击此处查找代码。无论何时写入使用access_debug日志格式的访问日志条目，都会对$json_debug_log变量进行估值。通过执行使用js_set指令定义的debugLogJavaScript 函数，对此变量进行估值。

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）、请求、上游和响应相关的信息时设置单独的对象。请注意在 NGINX 尝试为下一个成功响应的上游服务 (10.37.0.72) 之前，给第一个上游服务 (10.37.0.71) 返回状态码504``网关``超时的现象。前半秒超时（在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"
   }
}

结语

通过仅在遇到错误时生成丰富的诊断数据，我们可在无需执行任何重新配置的情况下，实时排除故障。而且，成功请求不会受到影响，因为 JavaScript 代码仅在日志记录阶段检测到错误时才运行，而在此之前最后一个字节已发送给客户端。

我们在GitHub上提供了完整的配置，您可以在自己的环境中尝试。如果尚未使用 NGINX Plus，可立即下载30 天免费试用版，或联系我们讨论您的用例。

更多资源

想要更及时全面地获取 NGINX 相关的技术干货、互动问答、系列课程、活动资源？

请前往 NGINX 开源社区：

• 官网：https://www.nginx.org.cn/
• 微信公众号：https://mp.weixin.qq.com/s/XVE5yvDbmJtpV2alsIFwJg
• 微信群：https://www.nginx.org.cn/static/pc/images/homePage/QR-code.png?v=1621313354
• B 站：https://space.bilibili.com/6283