NGINX.COM
电子书下载
Web Server Load Balancing with NGINX Plus
Liam Crilly of F5
F5 产品管理总监
2020-09-29

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

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

本文也是有关 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 配置以在生产环境中添加或删除日志记录详情，可能也要遵循变更控制流程，并重新部署配置。当解决实际问题时，例如“为什么会在 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 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 指令定义的 debugLog JavaScript 函数，对此变量进行估值。

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 天免费试用版，或联系我们讨论您的用例。

Tags
, , ,
Hero image
免费白皮书:
NGINX 企阅版全解析

助力企业用户规避开源治理风险，应对开源使用挑战

免费下载

关于作者

Liam Crilly

F5 产品管理总监

查看更多此作者的博文

关于 F5 NGINX

F5, Inc. 是备受欢迎的开源软件 NGINX 背后的商业公司。我们为现代应用的开发和交付提供一整套技术。我们的联合解决方案弥合了 NetOps 和 DevOps 之间的横沟，提供从代码到用户的多云应用服务。访问 nginx-cn.net 了解更多相关信息。

立即开始使用

试用 NGINX Plus

开始使用

向我们提出任何问题

联系我们