Nginx访问日志里的六个误读：内部跳转与重试

  1.  Home
  2. Text  
    3. Share to：

一、从一条日志说起

上周排查一个博客「发文章后首页不变」的问题，最后发现答案在一行日志里：

1.2.3.4 - - [23/Oct/2026:09:14:22 +0800] "GET / HTTP/1.1" 200 4127 "-" "Mozilla/5.0 ..."
1.2.3.4 - - [23/Oct/2026:09:14:23 +0800] "GET /index.php HTTP/1.1" 200 4127 "-" "Mozilla/5.0 ..."

同一个访客、间隔一秒、两个不同的 URI、两次 200、返回字节数一模一样。看起来是「两个页面」，实际上是一次内部跳转被记成了两次请求。这种情况如果不理解 Nginx 的内部跳转，看日志一定会误判——你会以为有人重复刷新，或者以为是 CDN 回源两次。

日志分析的价值不在「统计有多少 PV」，而在用日志还原请求真实走过的路径。这篇文章把 access.log 里最容易误读的几个字段讲透：内部跳转、$request_time 与 $upstream_response_time 的关系、上游失败与重试、静态兜底成 200 的软 404、以及缓存命中状态怎么从日志里读出来。

二、先把默认格式拆开

Nginx 默认的 combined 格式是这样定义的：

log_format combined '$remote_addr - $remote_user [$time_local] '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent"';

七个部分：客户端 IP、认证用户、时间、请求行、状态码、响应体字节数、Referer 和 UA。这里面有三个坑：

  • $body_bytes_sent 不包含响应头，也不包含 gzip 前的体积。想知道原始大小要用 $bytes_sent（含头）。
  • $request 是原始请求行，包含完整 URL 和 query string。如果 URL 里带了中文或空格，会显示成 \xE4\xB8\xAD 这种十六进制转义。
  • UA 里有空格，所以用 awk '{print $12}' 取 UA 一定错。正确做法是按引号切：awk -F'"' '{print $6}'（第 1 段是 IP 部分、第 2 段是请求行、第 4 段 Referer、第 6 段 UA）。

我自己用的格式在 combined 基础上加了五个字段，这一个改动让后面所有排查都变得可能：

log_format main '$remote_addr - $remote_user [$time_local] '
                '"$request" $status $body_bytes_sent '
                '"$http_referer" "$http_user_agent" '
                'rt=$request_time urt=$upstream_response_time '
                'uct=$upstream_connect_time uh=$upstream_addr '
                'cs=$upstream_cache_status host=$host '
                'reqid=$request_id';

关键提醒：log_format 是定义在 http 块里的，改完必须 nginx -t && nginx -s reload。reload 之后新旧日志行的字段数会不一致，所以改格式一定要配 logrotate，或者先 mv 掉旧文件再 reload，然后在分析脚本里按行判断是新旧格式。我吃过这个亏：一次改格式后分析脚本 awk 取第 9 列，结果一半行取到的是 rt=，一半取到的是别的字，报表直接错乱。

三、内部跳转：一次请求，两行日志

回到开头那个现象。Nginx 的 rewrite ... last、try_files 兜底、index 指令的补全、error_page 转向、以及 X-Accel-Redirect，都会产生内部跳转。内部跳转不经过网络，但在 Nginx 内部是一次新的 location 匹配，会再写一行 access_log。

3.1 怎么在日志里认出内部跳转

三个特征：

  • 同一个时间戳（秒级相同或差一秒）；
  • 同一个 $remote_addr；
  • reqid 相同——所以我在 log_format 里加了 $request_id。这是区分「内部跳转」和「用户真的点两次」的唯一可靠依据。没有 request_id 时只能靠时间戳+字节数猜，非常不可靠。

用 reqid 统计内部跳转的比例：

# 有多少个 request_id 产生了多于一行的日志
awk '{for(i=1;i<=NF;i++) if($i ~ /^reqid=/){split($i,a,"="); print a[2]}}' access.log \
 | sort | uniq -c | awk '$1>1' | wc -l

如果这个数字占总数比例很高（超过 20%），说明站点有大量内部跳转，可能来自 try_files 兜底或者伪静态规则链。内部跳转本身不是问题，但它会污染所有基于日志的统计：PV 被算成两倍、$request_time 被拆成两段、热门 URL 排行里混进 /index.php。

3.2 内部跳转对 $request_time 的影响

这一点最容易误判性能。假设用户请求 /post/123，Nginx 内部跳转到 /index.php：

  • 第一行日志（/post/123）的 $request_time 是完整的总耗时（包含内部跳转后的执行）；
  • 第二行日志（/index.php）的 $request_time 只是跳转之后那一段。

如果你用 index.php 那行统计「慢请求」，会系统性低估；如果用第一行统计，得到的是正确的总时间。所以在写慢请求分析的时候，一定要明确分析的是哪类 URI，或者直接统计「没有 reqid 重复的那些行」。

四、$request_time 与 $upstream_response_time

这两个字段的关系是理解整条链路的关键。定义上：

  • $request_time：从收到客户端第一个字节，到发送完最后一个字节的完整时间。包含 Nginx 读请求体、等 upstream、写响应、以及限速（limit_rate）造成的时间。
  • $upstream_response_time：只算和 upstream 打交道的时间。从建立连接到收完响应头/体。

所以 $request_time − $upstream_response_time ≈ Nginx 自身耗时 + 客户端网络时间。这个差值很有用：

4.1 差大说明什么

# 找 request_time 远大于 upstream 时间的请求：问题在 Nginx 或客户端
awk '{
  rt=urt=0
  for(i=1;i<=NF;i++){
    if($i ~ /^rt=/){split($i,a,"="); rt=a[2]}
    if($i ~ /^urt=/){split($i,b,"="); urt=b[2]}
  }
  if(rt>1 && (rt-urt)>0.8) print $7, "rt="rt, "urt="urt
}' access.log | head -20

常见原因按概率排：

  1. 客户端网络慢（尤其是移动端、跨境访问）：Nginx 已经发完了数据但客户端收得慢，send 缓冲满，Nginx 等 socket 可写。此时 $request_time 大而 urt 小，属于正常。
  2. limit_rate 限速：这是人为拖长的，日志里会看到大文件下载的 request_time 极大。
  3. gzip 动态压缩：CPU 吃紧的时候压缩大响应会占用 worker，此时 request_time 变大但 urt 正常。解决方式是 gzip_static on 用预压缩文件。
  4. 静态文件读盘慢：磁盘 IO 饱和，sendfile 卡住。这种情况 iostat 会同时报警。

4.2 urt 有多个值说明发生了重试

$upstream_response_time 在发生 upstream 重试时，会输出用逗号和冒号分隔的多个值，例如 urt=0.052, 3.001（两个上游各一次）或 urt=0.001 : 30.002（第一个超时，第二个成功）。同样 $upstream_addr 也会列出多个后端地址。

这个信号极其重要：只要 urt 里出现逗号，就说明这个请求经历过重试。而默认配置下 Nginx 会对 GET 和幂等请求自动重试下一个 upstream——这意味着一次用户点击可能在后端被处理两次。对于有副作用的接口（下单、扣款、发信），这会是灾难。

# 统计发生重试的请求比例
grep -c 'urt=[0-9.]*, ' access.log

规避方式：

upstream backend {
    server 127.0.0.1:9000 max_fails=3 fail_timeout=10s;
}
# 在 location 里关掉非幂等请求的重试
proxy_next_upstream error timeout http_502 http_503;
proxy_next_upstream_tries 2;
# 关键：让 POST 不重试
map $request_method $next_upstream {
    default "error timeout";
    POST    "";
}
proxy_next_upstream $next_upstream;

map 里给 POST 返回空字符串，等价于关闭 proxy_next_upstream（只有配了 off 才是彻底关闭，空值不触发任何条件）。这个写法比在每个 location 里复制一遍更省事。

五、软 404：日志里看起来是 200，其实是「页面不存在」

这是个人站长最容易忽略、对 SEO 伤害最大的一类问题。try_files 的兜底写错了，会让所有不存在的 URL 都返回 200 + 首页内容：

# 错误写法：不存在的 URL 返回首页，状态码 200
location / {
    try_files $uri $uri/ /index.html;
}
# 正确写法：静态站兜底必须是 404
location / {
    try_files $uri $uri/ =404;
}

前者在日志里表现为：GET /asdfghjkl.html 200 4127，而正常的文章页是 200 15800。所以光看状态码发现不了软 404，要看字节数：

# 找出返回 200 但字节数等于首页大小的请求
awk '$9==200 {print $7, $10}' access.log | awk '{print $2}' | sort -n | uniq -c | sort -rn | head -5

如果某个字节数出现频率异常高（比如 4127 出现了 3000 次），而且对应的 URI 五花八门，基本可以确认是软 404。数字本身不重要，重要的是「同一个字节数 + 不同 URI」这个组合。

顺带说一句：软 404 不只影响 SEO，还会让你 看不到攻击扫描。扫描器扫 /wp-login.php、/.env 的时候全部返回 200，日志里一片绿，你就以为风平浪静。

六、从日志读缓存命中状态

如果用了 fastcgi_cache 或 proxy_cache，加上 $upstream_cache_status（我在格式里叫 cs）就能看出每个请求的缓存命运：

# 缓存在各类状态下的占比
grep -o 'cs=[A-Z_]*' access.log | sort | uniq -c | sort -rn

七个值的含义要分清：

  • HIT：直接命中，最快；
  • MISS：没命中，回源了；
  • BYPASS：配置里 proxy_cache_bypass 生效（比如带登录 cookie），刻意跳过；
  • EXPIRED：有缓存但已过期，回源拿新的；
  • STALE：上游挂了，用旧内容顶着；
  • UPDATING：正在后台更新，本次返回旧的；
  • REVALIDATED：用 proxy_cache_revalidate 向源站确认后复用。

最重要的判断：如果 BYPASS 占比高得离谱（比如 60%），说明你的 bypass 规则把大多数请求都排除了——常见原因是 Set-Cookie 里有个 PHPSESSID，而你的规则是「有 cookie 就 bypass」。这时候缓存基本等于没开。修法是让 fastcgi_hide_header Set-Cookie，或者只在特定 cookie 上 bypass。

另外 cs=-（短横线）代表这次请求没有走缓存模块，通常是静态文件或者 location 没配 cache。看到大量 cs=- 而你以为开了缓存，说明 location 匹配没走到。

七、日志切分与「正在写入的那一半」

分析脚本最容易出的一个 bug：读 access.log 的时候 logrotate 正好在切，读到的是「一半老文件 + 一般新文件」，或者 wc -l 数到一行不完整的。三个防御手段：

  1. 分析已轮转的文件（access.log.1、access.log-20261022.gz），它们已经关闭，不会变；
  2. 如果必须读当前文件，先 cp 到临时目录再分析，或者用 tail -n +1 配合行尾完整性检查；
  3. 脚本里不要用 set -e——grep -c 没匹配到返回 1，会导致整个脚本静默退出，你看到的结果是「0」，而真相是「脚本根本没跑完」。

每日统计的标准姿势：

#!/bin/bash
# /root/daily-log.sh — 凌晨跑，分析昨天的日志
Y=$(date -d yesterday +%Y%m%d)
SRC="/var/log/nginx/access.log.1"      # logrotate 后的昨日文件
[ -f "$SRC" ] || { echo "缺 $SRC"; exit 1; }
TOTAL=$(wc -l < "$SRC")
PV=$(awk '$9==200' "$SRC" | wc -l)
P404=$(awk '$9==404' "$SRC" | wc -l)
SLOW=$(awk '{rt=0; for(i=1;i<=NF;i++) if($i ~ /^rt=/){split($i,a,"="); rt=a[2]} if(rt>1) c++} END{print c+0}' "$SRC")
echo "$Y total=$TOTAL pv200=$PV p404=$P404 slow1s=$SLOW"
# 404 top 路径（排除扫描器噪音）
awk '$9==404 {print $7}' "$SRC" | sed 's/?.*//' | sort | uniq -c | sort -rn | head -10

八、三个我踩过的误判

8.1 「日志里全是 CDN 节点 IP」

接入 CDN 后 $remote_addr 全变成 CDN 的 IP 段，此时所有基于 IP 的统计（独立访客、限速、封禁）全部失效。必须配 real_ip 模块，并且 set_real_ip_from 只能填 CDN 官方的回源段：

set_real_ip_from 173.245.48.0/20;   # 只填 CDN 段
set_real_ip_from 103.21.244.0/22;
real_ip_header CF-Connecting-IP;
real_ip_recursive on;

绝不能写 set_real_ip_from 0.0.0.0/0——那等于允许任何人伪造 X-Forwarded-For，你的 IP 限流、封禁、统计全部可被绕过。

8.2 「明明是 200，为什么用户说打不开」

可能的原因：状态码 200 但响应体为空（PHP 报致命错误被 display_errors=Off 吞掉，输出 0 字节）。看 $body_bytes_sent=0 的 200 请求：

awk '$9==200 && $10==0 {print $7}' access.log | sort | uniq -c | sort -rn | head

这个查询救过我一次：某个 PHP 页面在特定参数下直接 fatal，返回 200 空体，日志里看着一切正常，只有用户投诉。

8.3 「请求量翻倍了」

除了内部跳转，还有两个原因会让日志条数虚高：被 error_page 内部转向（404 → /404.html 会写两行），以及HEAD 请求（探针、监控、部分爬虫先发 HEAD）。统计时排除一下：

awk '$6 !~ /^"HEAD/ && $7 !~ /^\/404.html/' access.log | wc -l

九、最小可用的日志仪表盘

不需要 ELK，也不需要 Prometheus，四个数字 + 两个榜单就能覆盖日常 90% 的问题：

  • 四个数字：总请求、5xx 数、P95 request_time、缓存命中率（HIT / 总数）；
  • 两个榜单：404 top10（找软 404 和被扫描的路径）、慢请求 top10（带 urt 拆分，判断是 PHP 慢还是 Nginx 慢）。

P95 的计算不用装工具，一行 awk 就够：

awk '{for(i=1;i<=NF;i++) if($i ~ /^rt=/){split($i,a,"="); print a[2]}}' access.log \
 | sort -n | awk '{v[NR]=$1} END{print "p50="v[int(NR*0.5)], "p95="v[int(NR*0.95)], "p99="v[int(NR*0.99)]}'

把这些存成每天的 CSV，一个月后你就能看出趋势：是内容变多导致变慢，还是某个版本上线后 P95 抬了一个台阶。运维里最有用的能力不是「出问题能查」，而是「不出问题的时候也能看出苗头」，日志就是最便宜的那双眼睛。

Last modification：October 23rd, 2026 at 09:25 pm
© 允许规范转载

相关文章

Leave a Comment