手记 005：nginx 日志分析器 v2 —— 变量名冲突的隐蔽性

日期: 2026-09-21 用时: 约 120 分钟 难度: ⭐⭐⭐⭐☆

---

1. 任务

在 v1（仅统计状态码）基础上，为 nginx 日志分析器增加四项功能：

1. 404 路径统计
2. 429 限流分析
3. 扫描器特征识别
4. 支持 .gz 压缩日志

同时建立了本地开发环境（Windows + PyCharm + git）， 代码在本地编写、推送到私有仓库、服务器拉取执行。

---

2. 核心问题：变量名冲突

本次遇到两个 bug，第一个花了较长时间才定位。

2.1 症状

程序运行到输出文件统计表时报错：

File "quests/log-analysis.py", line 368, in run
    name = os.path.basename(path)
TypeError: expected str, bytes or os.PathLike object, not NoneType

进一步调试发现，stats.files 列表里的内容不对：

stats.files 条目数: 8
  [0] len=5  path=None                    ← 应该是文件路径
  [1] len=5  path='/manager/text/list'    ← 这是日志里的 URL！
  [2] len=5  path='/'
  [3] len=5  path='/hotel/'

文件统计表里显示的应该是文件名，实际却变成了 URL 路径。

2.2 根因

def analyze_file(path, stats):      # ← path 是「日志文件路径」
    ...
    for lineno, raw in enumerate(fh, 1):
        ...
        kind, path = classify_request(req)   # ← path 被「URL 路径」覆盖！
        ...
    stats.files.append((path, lines, parsed, skipped, None))
    #                    ↑ 此时它已经是 URL 了

classify_request() 返回的第二个值是 URL 路径，而代码用 path 这个名字接收它—— 恰好和函数参数 path（日志文件路径）同名。

Python 不会报错，因为在同一个函数作用域里，重新赋值是合法的。 但循环结束后，path 已经变成最后一次迭代的 URL。

2.3 复现演示

用一个最小例子可以清楚看到后果：

def process(path, items):
    for item in items:
        kind, path = ("url", item)      # 覆盖了函数参数
    print(repr(path))

process("/var/log/app.log", ["/login", "/admin", "/api"])

输出：

'/api'                          ← 期望是 '/var/log/app.log'

正确写法：用不同的变量名。

def process_fixed(path, items):
    for item in items:
        kind, item_path = ("url", item)   # 名字不冲突
    print(repr(path))

process_fixed("/var/log/app.log", ["/login", "/admin", "/api"])

输出：

'/var/log/app.log'              ← 正确

2.4 为什么这个错误特别危险

特性	说明
语法完全合法	py_compile 通过
静态检查不报错	pyflakes 通过（没有未定义名称）
程序能运行	只是结果错了
错误位置隐蔽	症状出现在「输出阶段」，根因在「解析阶段」
不影响主流程	状态码统计等其他功能全部正常

这符合之前几个任务反复出现的模式：

代码「能跑通」和「结果正确」是两件事。

而这次的独特之处在于：它不是语法错误、不是逻辑错误， 而是「命名不当导致的状态污染」——这类问题只能靠检查输出内容发现。

2.5 修复

把 URL 路径改名为 req_path：

kind, req_path = classify_request(req)

if kind == 'empty':
    ...
else:
    stats.path_all[req_path] += 1
    if status == '404':
        stats.path_404[req_path] += 1
    sp = match_sensitive_path(req_path)

并在代码里加了注释说明这个坑：

# 注意变量命名：这里用 req_path 而不是 path，
# 因为 path 是函数参数（日志文件路径），不能被覆盖。
# （v2 初版就是踩了这个坑：path 被 URL 覆盖，导致文件统计表全错）

---

3. 第二个 bug：时间范围取值错误

3.1 症状

时间范围显示成了反向的：

时间范围：21/Sep/2026:03:58:08  →  21/Sep/2026:03:41:56
         └─────── 较晚 ────┘      └─────── 较早 ────┘

起点比终点还晚。

3.2 根因

原实现取的是「第一行」和「最后一行」：

if stats.time_min is None:
    stats.time_min = tstr      # 第一行
stats.time_max = tstr           # 每一行都覆盖 → 最终是最后一行

但文件是按文件名排序处理的：

/var/log/nginx/personal-site.access.log              ← 最新（今天）
/var/log/nginx/personal-site.access.log-20260915.gz  ← 最旧
/var/log/nginx/personal-site.access.log-20260916.gz
...
/var/log/nginx/personal-site.access.log-20260921

glob.glob() 按文件名字典序返回，不等于时间顺序。

「第一行」和「最后一行」只在单个文件内成立，跨文件时不成立。

3.3 修复

解析成 datetime 对象后，取全局最小 / 最大：

dt = parse_time(tstr)
if dt is not None:
    if stats.time_min is None or dt < stats.time_min:
        stats.time_min = dt
    if stats.time_max is None or dt > stats.time_max:
        stats.time_max = dt

修复后：

时间范围：2026-09-13 15:07:25  →  2026-09-21 13:30:59
跨度：    7 天 22 小时

---

4. 四项功能的实现

4.1 支持 .gz 压缩日志

def open_log(path):
    if path.endswith('.gz'):
        return gzip.open(path, 'rt', errors='replace')   # 'rt' = 文本模式
    return open(path, 'r', errors='replace')

关键点是 'rt' —— 文本模式让 Python 自动解码为 str， 省去手工 decode()。配合 errors='replace' 处理编码异常。

实测：8 个日志文件中 6 个是 .gz，全部正常读取。

4.2 404 路径统计与敏感路径标注

SENSITIVE_PATH_PATTERNS = [
    (r'^/\.env', '环境变量文件'),
    (r'^/\.git', 'Git 仓库'),
    (r'^/wp-admin|^/wp-login', 'WordPress'),
    (r'^/phpmyadmin|^/pma', 'phpMyAdmin'),
    (r'^/admin|^/manager|^/console', '管理后台'),
    (r'^/actuator', 'Spring Actuator'),
    (r'^/config|^/backup|^/dump', '配置/备份文件'),
    ...
]

输出时自动标注路径类型，让报告更有可读性：

/SDK/webLanguage     51 次  ← SDK 接口探测
/login               32 次  ← 登录页
/admin/config.php    15 次  ← 管理后台
/phpinfo.php         11 次  ← PHP 脚本

4.3 429 限流分析：区分本机与外部

这个设计考虑了「数据来源的可靠性」：

local_429 = sum(n for ip, n in stats.ip_429.items() if ip.startswith('127.'))
extern_429 = n429 - local_429

输出：

被限流请求共 9615 次
  · 本机（压测/测试）:   9615 次
  · 外部客户端:             0 次

注意：全部限流来自本机，属于压测流量。
      当前没有外部 IP 触发限流阈值。

为什么必须区分：如果不区分，报告会显示「9615 次限流」， 让人误以为「遭受了严重的攻击」——实际上是自己的压测产生的。

这个原则可以推广：分析数据时，必须区分「自己的测试流量」和「真实业务流量」。

4.4 扫描器识别：多特征打分

没有用「单条件判断」，而是打分模型：

score = 0

# 404 占比
if n >= 3 and ratio >= 0.5:
    score += 2      # 大量 404
elif n404 > 0:
    score += 1

# 协议错配（TLS/SSH 发到 HTTP 端口）
if has_proto:
    score += 2

# 自动化客户端 UA
if has_ua:
    score += 1

# 探测敏感路径
if has_sens:
    score += 1

为什么用打分而不是单条件：

单条件的问题	打分模型
只有 404 多 → 可能是链接失效	多个特征同时命中才判高危
只有 UA 可疑 → 可能是正常爬虫	降低误报
只有协议错配 → 可能是客户端 bug	综合判断

实测输出：

[高] 80.87.206.229   36 次请求  404 占比 89%、协议错配、自动化 UA、探测敏感路径
[高] 45.138.12.51    34 次请求  404 占比 82%、协议错配、自动化 UA、探测敏感路径
[高] 216.180.246.219 21 次请求  404 占比 62%、协议错配、自动化 UA、探测敏感路径

识别出的特征类型（24 种）：

自动化客户端：curl                          875 次   9 个 IP
自动化客户端：无 User-Agent                 644 次  229 个 IP
TLS 握手发到 HTTP 端口                      266 次  125 个 IP
自动化客户端：zgrab                         130 次   74 个 IP
自动化客户端：Censys 测绘                    55 次   29 个 IP
自动化客户端：nmap                           24 次    3 个 IP
探测敏感路径：SDK 接口探测                    53 次    3 个 IP
探测敏感路径：管理后台                        38 次   25 个 IP
探测敏感路径：PHP 脚本                       37 次   11 个 IP
探测敏感路径：Spring Actuator                17 次   11 个 IP
SSH 协议发到 HTTP 端口                        7 次    7 个 IP

---

5. 实测数据

日志文件：8 个（其中 6 个 .gz），共 12500 行
时间范围：2026-09-13 15:07:25 → 2026-09-21 13:30:59（跨度 7 天 22 小时）

状态码分布：
  429   9615 次  76.9%     ← 全部来自本机压测
  200   1532 次  12.3%
  404    783 次   6.3%
  400    547 次   4.4%
  405     13 次   0.1%
  304      6 次
  403      2 次
  413      2 次

404 分析：
  783 次响应，涉及 280 个不同路径

限流分析：
  9615 次全部来自 127.0.0.1（本机压测），外部 IP 0 次

扫描器：
  24 种特征类型，10 个高危可疑 IP

结论的价值：

观察	结论
4xx 占比 87.7%	存在明显的扫描或探测活动
限流全部来自本机	外部 IP 未触发速率阈值，说明限流配置合理
无 5xx 错误	服务端未出现故障
24 种扫描特征	服务器处在活跃的互联网扫描环境中

---

6. 本地开发环境的建立

本次同时完成了开发工作流的搭建：

本地 Windows (D:\python\aliyun-ops-practice)
  ├─ PyCharm 编写代码
  ├─ git commit
  └─ git push ─────────────────┐
                                │
                                ▼
                    GitHub 私有仓库
                    <你的用户名>/<仓库名>
                                │
                                │ git pull
                                ▼
              阿里云 ECS (/root/ops-lab)
              └─ 运行验证

配置过程中解决了两个环境问题：

问题 1：GitHub 连接被 hosts 文件劫持

Resolve-DnsName github.com 返回 127.0.0.1。

排查发现 C:\Windows\System32\drivers\etc\hosts 中有 30 多条 GitHub 相关域名被指向 127.0.0.1，来源是 Watt Toolkit （GitHub 加速工具）的「Hosts 代理模式」。

该工具只代理 HTTPS（443），不代理 SSH（22）， 因此 ssh -T git@github.com 一直返回 Connection refused。

解决方案：改用 GitHub 官方支持的 SSH over 443：

Host github.com
  HostName ssh.github.com
  Port 443
  User git
  IdentityFile ~/.ssh/github_ops_lab_local

问题 2：Git 自带的 ssh 读不到配置文件

解决网络问题后，git fetch 仍然尝试连接 22 端口。

根因：Git for Windows 自带一个 MSYS2 编译的 ssh.exe， 它的 HOME 判定方式与 Windows 原生 ssh 不同， 找不到 C:\Users\<name>\.ssh\config。

解决方案：

git config --global core.sshCommand "C:/Windows/System32/OpenSSH/ssh.exe"

显式指定使用 Windows 原生的 ssh。

问题 3：换行符策略

Git 提示 LF will be replaced by CRLF。

风险：仓库中有 15 个 .sh 脚本，如果被转换成 CRLF， 在 Linux 上执行会报：

/bin/bash^M: bad interpreter: No such file or directory

解决方案：添加 .gitattributes：

*.sh text eol=lf
*.py text eol=lf
*.md text eol=lf
*.bat text eol=crlf
*.ps1 text eol=crlf

---

7. 结论

变量命名是防御性编程的一部分

path 被覆盖这个 bug 的特征是：

• 语法合法
• 静态检查通过
• 程序能运行
• 只是结果不对

Python 中函数参数在函数体内可被重新赋值，这既是灵活性，也是隐患。

防范方式：

方式	说明
命名要具体	req_path 比 path 明确，不易与参数撞名
避免复用循环变量	元组解包时尤其注意
不覆盖函数参数	需要中间值时用新名字
检查输出内容	这是最后一道防线

"第一行/最后一行"不等于"最早/最晚"

时间范围那个 bug 暴露了一个常见假设错误： 代码的执行顺序不等于数据的逻辑顺序。

文件按名字排序，而名字的字典序与时间是巧合关系， 不是保证关系。任何跨越多个数据源的范围计算都必须实际比较。

分析数据时必须区分数据来源

429 限流分析里，那 9615 次限流全部来自本机压测。 如果不区分本机和外部，报告读起来像是服务器被攻击了 —— 但实际只是我自己在测试。

所以看数据之前先确认它是怎么产生的。

多特征打分的误报控制优于单条件判断

扫描器识别的准确率取决于是否用多个独立特征交叉验证。 单条件（比如只看 404 占比）会把「链接失效」误判为「扫描」， 而多条件同时命中才判定，显著降低了误报。

---

8. 协作说明

本文的 v2 代码（623 行）是在 AI 辅助下生成的。

分工大致是：需求描述、环境搭建、执行操作、问题发现和结果验证由我做； 代码生成和排查方向的引导由 AI 提供。

过程中有两点印象比较深。

一是需求描述要具体。"分析 429 限流"这句话，如果不说明要区分本机压测和外部流量、 要输出什么格式，拿到的东西就用不上。

二是发现问题需要先理解代码在做什么。变量名冲突那个 bug 的表现是 统计表里显示 URL 而不是文件名 —— 要先知道 stats.files 应该存什么， 才能判断出存错了。

---

9. 遗留

log-analysis.py 目前已具备四项主要功能（623 行）。 后续可考虑增加：

• 命令行参数解析（argparse）：时间过滤、输出格式、TOP N 可配置
• 输出到文件（当前只打印到终端）
• 独立的扫描器指纹库（当前特征硬编码在代码里）

---

10. 后续计划

1. 将日常巡检脚本 daily-check.py 正式落地（此前只完成框架填写）
2. 编写仓库 README
3. 继续扩充故障复盘与手记

可用键盘 ← → 切换上下篇