Appearance

Nginx日志、分段耗时与生产故障取证 ​

线上出现“接口慢”“大量499”“偶发502”时，只看一条error log通常无法得出根因。Nginx处在客户端和后端之间，必须同时记录客户端、请求路由、每次upstream尝试、分段耗时、最终状态和Request ID，才能还原完整时间线。

学习目标 ​

  1. 区分access log、error log、系统指标和后端APM的证据边界。
  2. 解释request、connect、header、response四类耗时。
  3. 还原一次首节点失败、次节点成功的重试链。
  4. 区分499、502、503、504及其责任边界。
  5. 正确配置日志格式、缓冲、轮转、容器标准流和脱敏。
  6. 按CPU、连接、FD、磁盘、TLS和upstream逐层排查。

一、一次请求需要哪些证据 ​

mermaid
flowchart TD
    A["客户端请求"] --> B["Nginx access log"]
    B --> C["Nginx error log"]
    C --> D["upstream应用日志/APM"]
    D --> E["数据库、Redis、MQ指标"]
    B --> F["宿主机或容器CPU、内存、FD、网络、磁盘"]
证据能回答什么不能单独证明什么
access log谁在何时请求、最终状态、耗时和upstream后端内部为什么慢
error log建连、TLS、文件、upstream等错误细节所有成功慢请求原因
APM/应用日志Java线程、SQL、下游调用客户端是否提前断开
系统指标CPU、FD、磁盘、网络是否饱和哪个业务请求造成
发布记录版本、配置和流量变化根因本身

二、最小生产日志格式 ​

nginx
log_format production
    'time=$time_iso8601 request_id=$request_id '
    'remote_addr=$remote_addr host=$host '
    'request="$request" status=$status bytes=$body_bytes_sent '
    'request_length=$request_length request_time=$request_time '
    'upstream_addr="$upstream_addr" upstream_status="$upstream_status" '
    'upstream_connect="$upstream_connect_time" '
    'upstream_header="$upstream_header_time" '
    'upstream_response="$upstream_response_time" '
    'referer="$http_referer" user_agent="$http_user_agent"';

access_log /var/log/nginx/access.log production;

日志格式需要稳定版本管理。字段含义变化时应同步日志平台解析规则，避免上线后所有字段错位。

三、Request ID如何贯穿链路 ​

nginx
proxy_set_header X-Request-Id $request_id;
add_header X-Request-Id $request_id always;
mermaid
flowchart TD
    A["Nginx生成或接收受信Request ID"] --> B["写入access log"]
    B --> C["传给Spring Boot"]
    C --> D["写入应用MDC日志"]
    D --> E["传给下游HTTP/RPC/MQ"]

如果允许客户端提供Request ID，应校验长度和字符，避免日志注入与高基数攻击。入口可保留原始ID到单独字段，再生成内部可信ID。

四、request_time到底包含什么 ​

$request_time通常从Nginx读取客户端请求的首批字节开始，到请求处理结束并写日志为止。它可能包含：

  • 客户端慢慢发送Header和Body。
  • limit_req延迟。
  • upstream建连和处理。
  • 多次upstream重试。
  • Nginx Filter处理。
  • 向慢客户端发送响应。

因此request_time高不等于后端一定慢。

五、三类upstream分段耗时 ​

变量主要含义高值方向
$upstream_connect_time建立上游连接，HTTPS还可能包含TLS握手网络、SYN队列、防火墙、TLS、后端accept
$upstream_header_time从开始处理上游到收到响应HeaderJava排队、业务处理、慢SQL、下游调用
$upstream_response_time完成该次upstream响应的时间响应生成、流式传输、大响应、网络

Keep-Alive复用连接时connect time可能接近0。不能因为0就认为网络从未出问题，只表示这次可能没有新建连接。

六、如何用差值定位阶段 ​

示例：

text
request_time=5.20
upstream_connect=0.01
upstream_header=4.90
upstream_response=5.00

推断：建连快，主要时间花在后端返回Header之前，应查Java线程池、SQL和下游。

另一个例子：

text
request_time=12.00
upstream_response=1.20

差距很大，可能是客户端上传慢、limit_req排队、向慢客户端发送或多阶段处理。差值是线索，不是自动根因。

七、多次重试日志怎么读 ​

upstream变量可能记录多个地址、状态和时间：

text
upstream_addr="10.0.1.11:8080, 10.0.1.12:8080"
upstream_status="502, 200"
upstream_connect="0.001, 0.002"
upstream_response="0.020, 0.080"
status=200

说明首节点失败后重试次节点成功。只看最终200会掩盖节点故障和额外负载。分隔格式在跨upstream组和不同版本中可能有差异，日志解析应使用真实样本验证。

八、499是什么意思 ​

499是Nginx常用的非标准状态，表示客户端在Nginx完成响应前关闭连接。可能原因：

  • 用户取消请求。
  • 浏览器切页。
  • 移动网络断开。
  • 上层LB超时短于Nginx。
  • 客户端SDK超时并重试。
  • 后端太慢，客户端等不及。
  • limit_req排队超过客户端超时。

499不是简单的“客户端问题”。如果后端P99升高后499同步上涨，根因很可能仍在服务端链路。

九、502、503和504 ​

502 Bad Gateway ​

Nginx没有获得有效上游响应：DNS失败、连接拒绝、协议不匹配、上游提前关闭、响应格式无效或所有节点不可用。

503 Service Unavailable ​

可能来自业务upstream，也可能由限流默认状态、维护配置、无可用节点等产生。必须结合error log和upstream_status区分是谁返回。

504 Gateway Timeout ​

建立连接或读取上游响应超过超时，常见于慢SQL、线程池/连接池排队、下游慢、网络静默丢包和重试时间过长。

十、error_log级别 ​

nginx
error_log /var/log/nginx/error.log warn;

常见级别从严重到详细包括emerg、alert、crit、error、warn、notice、info、debug。生产长期debug可能产生巨大日志和性能开销。

Debug日志还可能要求Nginx构建时启用debug能力：

bash
nginx -V

可以结合events中的 debug_connection 对特定来源缩小范围，但仍需确认版本、编译参数和敏感信息风险。

十一、access_log缓冲 ​

高QPS下每请求同步写日志会增加系统调用和磁盘压力。可评估：

nginx
access_log /var/log/nginx/access.log production buffer=64k flush=1s;

缓冲减少写次数，但进程异常时可能丢失尚未flush的数据；日志实时性也会降低。对审计级日志还需外部可靠采集和业务落库，不能只靠本地access log。

十二、条件日志不要隐藏故障 ​

可用map控制部分日志：

nginx
map $status $loggable {
    ~^[23] 0;
    default 1;
}

access_log /var/log/nginx/error-access.log production if=$loggable;

这只适合额外错误日志，不应轻率替代完整访问日志。若只记录4xx/5xx，会丢失慢200、重试后200和流量基线。

十三、敏感信息脱敏 ​

不要直接记录：

  • Authorization。
  • Cookie和Set-Cookie。
  • Token、AK/SK和签名密钥。
  • 密码、身份证、手机号全文。
  • 完整支付报文。
  • 未脱敏查询参数和请求体。

URI查询参数也可能包含Token。更安全的做法是应用层结构化记录允许字段，入口日志只记录路由模板、状态、耗时和Request ID。

十四、日志轮转原理 ​

Linux上常见流程：

text
重命名当前日志文件
→ 向Nginx master发送USR1
→ master重新打开日志并调整权限
→ worker切换到新文件描述符
→ 压缩和保留旧文件

只重命名文件而不让Nginx reopen，进程仍可能通过旧FD继续写被重命名文件。copytruncate存在复制期间丢失或重复窗口，不是所有场景最佳方案。

十五、容器日志边界 ​

官方容器镜像常把access/error log链接到stdout/stderr：

text
Nginx日志
→ stdout/stderr
→ Docker日志驱动
→ 日志采集器

此时轮转通常由Docker日志驱动或平台负责。把空目录挂载到 /var/log/nginx可能遮住符号链接，导致 docker logs看不到日志。

十六、变量日志路径与open_log_file_cache ​

按虚拟主机动态路径：

nginx
access_log /var/log/nginx/$host.access.log production;

会带来大量动态文件打开与安全风险。$host必须受server匹配和路径策略约束，不能让未受信输入任意构造文件路径。open_log_file_cache可缓存日志文件描述符，但参数、失效和错误处理需按版本文档配置。

商业系统更推荐统一结构化日志，在字段中记录host/tenant，由日志平台分流，而不是为每个租户创建本地文件。

十七、基础状态指标 ​

开源Nginx可通过stub_status等能力观察活动连接、accept、handled和requests，具体模块需检查：

bash
nginx -V

状态接口必须仅对受控管理网络开放，不暴露公网。还需结合Prometheus exporter或平台指标采集：

  • QPS与状态码。
  • 活动连接。
  • P50/P95/P99。
  • upstream分节点错误和耗时。
  • TLS握手。
  • 限流命中。
  • CPU、内存、FD、网络、磁盘。

十八、CPU高排查 ​

bash
ps -o pid,ppid,psr,pcpu,pmem,cmd -C nginx
top -H -p <worker-pid>

关联：TLS握手洪峰、gzip、大响应、复杂正则、恶意URI、第三方模块、Lua脚本、重试放大和容器CPU throttling。CPU已经饱和时增加Worker可能只增加调度竞争。

十九、连接与FD排查 ​

bash
ss -s
ss -antp
cat /proc/<worker-pid>/limits
ls /proc/<worker-pid>/fd | wc -l

按状态看SYN_RECV、ESTABLISHED、TIME_WAIT、CLOSE_WAIT；再区分客户端连接、upstream连接、WebSocket、keep-alive和文件FD。提高上限前先查连接为什么不结束。

二十、磁盘与日志排查 ​

bash
df -h
df -i
du -sh /var/log/nginx
lsof +L1

区分容量满、inode满、deleted-open文件、日志无轮转、proxy临时文件和缓存目录。删除仍被进程打开的文件名不一定立即释放空间，需要确认FD和安全reopen。

二十一、TLS排查 ​

分层检查：

  1. 443是否监听和发布。
  2. SNI是否命中正确server。
  3. 证书域名、有效期和完整链。
  4. TLS版本与Cipher兼容。
  5. 私钥权限。
  6. 上游是否也使用TLS及其证书验证。
  7. 系统时间。

TLS握手失败发生在HTTP请求前，可能没有普通access log，需要error log和外部TLS探测。

二十二、生产故障前五分钟 ​

mermaid
flowchart TD
    A["记录故障时间、域名、URI和发布变化"] --> B["确认影响范围与状态码"]
    B --> C["保存access/error log样本"]
    C --> D["比较request与upstream分段耗时"]
    D --> E["按upstream_addr拆节点"]
    E --> F["检查CPU、连接、FD、磁盘和网络"]
    F --> G["关联应用APM、DB、Redis和MQ"]
    G --> H["止损、回滚或限流"]

不要先重启清空现场。若必须止损，先保存时间窗口日志、指标截图、配置版本、Worker状态和upstream分布。

二十三、商业场景：499突然升高 ​

现象：移动端499增加，Nginx CPU正常。日志显示request_time约3秒，upstream_header_time约2.8秒；移动端超时2秒并立即重试。

根因：后端慢于客户端超时，客户端先断开；重试进一步放大后端压力。治理应查慢SQL/线程池并统一超时与退避，而不是把499全部归咎客户端。

二十四、商业场景：最终200掩盖坏节点 ​

日志最终status=200，但upstream_status是 502, 200。首节点持续失败，Nginx每次重试次节点，错误率看似正常但延迟与后端负载增加。应按每次upstream尝试告警并摘除/修复坏节点。

二十五、面试标准回答 ​

request_time和upstream_response_time区别 ​

request_time覆盖Nginx看到的整个请求生命周期，可能包含客户端上传、限流等待、上游、多次重试和向慢客户端发送；upstream_response_time描述每次上游响应阶段。前者明显大于后者时，要查客户端、排队、重试和响应发送，不能直接认定后端慢。

499是什么 ​

499表示客户端在Nginx完成响应前关闭连接，可能是用户取消、网络断开、上层LB/SDK超时或后端太慢。它不是纯客户端责任；应把499时间线与upstream耗时、客户端超时和重试一起分析。

为什么最终200仍要看upstream_status ​

Nginx可能首节点失败后重试另一节点成功，最终status是200，但upstream地址、状态和耗时会记录多次尝试。只监控最终5xx会掩盖坏节点、重试风暴和额外延迟。

日志文件改名后为什么磁盘还不释放 ​

进程仍持有旧文件描述符并继续写入，文件名删除或重命名不等于磁盘块立即释放。应检查deleted-open FD，按受控轮转向Master发送日志reopen信号，再确认新旧FD和采集器。

二十六、学习验收 ​

  1. 设计包含Request ID、upstream地址、状态和分段耗时的日志。
  2. 给三组耗时推导客户端慢、建连慢和后端首包慢。
  3. 从多值upstream变量还原一次重试链。
  4. 分别解释499、502、503和504。
  5. 完成日志缓冲、轮转、reopen和容器标准流实验。
  6. 证明删除日志名不一定释放deleted-open空间。
  7. 按CPU、连接、FD、磁盘和TLS完成一次Runbook。
  8. 保证日志不泄露Token、Cookie和个人敏感信息。

关联知识点 ​