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

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

编辑器– 该博客是讨论使用 NGINX 和 NGINX Plus进行日志记录的几个博客之一。 另请参阅：

• 使用 NGINX 和 NGINX Plus 进行application跟踪
• 使用 NGINX 条件日志记录对请求进行采样

它也是关于 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; # 使用 'main' 格式记录
error_log /var/log/nginx/error.log warn; # 记录至 'warn' 严重性级别
...
}

log_format指令描述了在配置中包含access_log指令时创建的日志条目的内容和结构。 上面的例子是许多 Web 服务器使用的通用日志格式(CLF) 的扩展。 使用error_log指令，您可以指定要记录的消息的严重性级别，但不能指定固定的条目的内容或格式。 下一节将对此进行更多介绍。

NGINX 日志的其他值得注意的方面包括：

• 日志指令会被低级配置上下文自动继承。 例如， http上下文中的access_log指令应用于所有server{}块。
• 子上下文中的日志指令会覆盖继承的指令。
• 在同一个上下文中可能存在多个日志指令。 例如，可以使用两个access_log指令来创建标准 CLF 日志文件和第二个更详细的日志。

生产中的日志记录现实

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

• 访问日志缺乏足够的详细信息以进行故障排除
• 错误日志在信息严重性级别上披露了很好的细节，但对于正常操作来说太冗长了
• 错误日志格式是固定的，因此无法定制以包含特别感兴趣的变量
• 错误日志中的条目不包含请求的上下文，很难与相应的访问日志条目匹配

此外，在生产环境中更改 NGINX 配置以添加或删除日志详细信息可能还需要经过变更控制过程，并重新部署配置。 非常安全，但在解决实时问题时有些麻烦，例如“为什么我看到4xx / 5xx错误？”。 当集群中有多个 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好的。 一个这样的例子是当 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 提供了超过 100 个与 HTTP 处理相关的变量，我们可以定义一个特殊的log_format指令来捕获我们需要的任意数量的变量。 然而，为此目的构建一个简单的日志格式也存在一些缺点。

• 这是一种自定义格式——你需要训练日志解析器如何读取它
• 在实时故障排除过程中，条目可能很长，人类难以阅读
• 您需要不断参考日志格式来解释条目
• 无法记录非确定性值，例如“所有请求标头”

我们可以通过使用NGINX JavaScript 模块<.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; # 卸载到 njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

js_import指令指定包含 JavaScript 代码的文件并将其作为模块导入。 代码本身可以在这里找到。 每当我们编写使用access_debug日志格式的访问日志条目时，都会评估$json_debug_log变量。 通过执行js_set指令定义的debugLog JavaScript 函数来评估此变量。

JavaScript 代码和 NGINX 配置的组合会产生如下所示的诊断日志。

$ tail --lines=1 /var/log/nginx/access_debug.log | jq { “时间戳”： “2020-09-21T11：25：55 + 00：00”，“连接”：{“请求计数”： 1，“已用时间”： 0.555，“管道化”：false，“ssl”：{“协议”： “TLSv1.2”，“密码”： “ECDHE-RSA-AES256-GCM-SHA384”，“session_id”：“b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c”，“session_reused”：false，“client_cert”：{“status”： “无” } } }, “请求”：{ “客户端”： “127.0.0.1”，“端口”： 443，"主机"："foo.example.com"，"方法"： “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”，“服务器端口”： 443，"connect_time"：null，"header_time"：null，"response_time"： 0.551，“已发送字节数”： 0，"已接收字节数"： 0，“状态”： 504 }, { "服务器地址": “10.37.0.72”，“服务器端口”： 443，"连接时间": 0.004，“header_time”： 0.004，“响应时间”： 0.004，“已发送字节数”： 92，"bytes_received": 4161，"状态"： 200 } ], "响应": { "状态": 200，"已发送字节数"： 186，"标题"：{"内容类型"："text/html"，"内容长度"： “4161” } } }

JSON 格式使我们能够拥有与整体 HTTP 连接（包括 SSL/TLS）、请求、上游和响应相关的信息的单独对象。 注意第一个上游（10.37.0.71）如何返回状态504（网关超时）之后，NGINX 尝试下一个上游（10.37.0.72），并成功响应。 半秒超时（在上游对象的第一个元素中报告为response_time ）占此成功响应的大部分总体延迟（在连接对象中报告为elapsed_time ）。

这是（截断的）日志条目的另一个示例，针对由于客户端证书过期而导致的客户端错误。

{ 
“时间戳”： “2020-09-22T10:20:50+00:00”,
“连接”: {
“ssl”: {
“协议”: “TLSv1.2”,
“密码”: “ECDHE-RSA-AES256-GCM-SHA384”,
“session_id”: “30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e”,
“session_reused”: false,
“client_cert”: {
“status”: “失败：证书已过期”,
“序列号”: "1006",
"指纹": “0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d”,
“主题”：“emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US”,
“发行人”: “CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US”,
“启动”: “2019 年 9 月 20 日 12:00:11 GMT”
“到期”： “2020 年 9 月 20 日 12:00:11 GMT”，
“已过期”：true，
...
“响应”：{
“状态”： 400,
“bytes_sent”: 283,
“标题”：{
“内容类型”：“text/html”，
“内容长度”： “215”
}
}

概括

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

完整的配置可以在GitHub上找到——为什么不在您的环境中尝试一下？ 如果您尚未运行 NGINX Plus，请立即开始30 天免费试用或联系我们讨论您的用例。