103 lines
5.5 KiB
Markdown
103 lines
5.5 KiB
Markdown
---
|
||
title: "9395 条日志，没有一声报警"
|
||
description: "一个日志文件，整天只写了 3 条。不是没人访问，是日志系统自己静默失败了——而且它失败的方式，正是我们最该监控的那种。"
|
||
date: 2026-09-11T21:40:00+08:00
|
||
draft: false
|
||
tags:
|
||
- 运维
|
||
- 可观测性
|
||
- 日志
|
||
- 事故复盘
|
||
---
|
||
|
||
## 开场：一个只有 3 条的日志文件
|
||
|
||
盘点日志覆盖情况时，发现一件怪事：**某天的结构化日志文件只有 3 条记录**。
|
||
|
||
而其他日子都是 1 到 2 万条。
|
||
|
||
那天没人访问吗？不是——业务数据表里，那天的 API 调用、客户端操作、快照全都在。**只是日志没写进去。**
|
||
|
||
## 破案：一个权限，一个 @
|
||
|
||
顺着文件属主一查，事故链清清楚楚：
|
||
|
||
1. 凌晨，一个定时任务以 **root** 身份执行（容器默认身份）
|
||
2. root 顺手创建了当天的日志文件，权限 `644 root:root`
|
||
3. 之后应用进程（`www-data`）想追加写入 → **Permission denied**
|
||
4. 而写日志的代码用的是 **`@file_put_contents`**——那个 `@` 把错误静静吞掉了
|
||
|
||
于是：**全天 9395 个请求的日志，一条都没落盘，没有任何报警。**
|
||
|
||
这个失败方式的讽刺之处在于：`@` 是为了"日志写不进去也不该影响业务"——这个取舍本身没错。但结果是，**日志系统悄悄死了，而唯一能告诉我们它死了的，也是日志**。
|
||
|
||
## 第二个盲区：原生错误从不进日志
|
||
|
||
继续盘点，发现了更隐蔽的一层。
|
||
|
||
在结构化日志里搜三类近期修过的代码异常（一个计数器回归、一个页面变量缺失、一个方法可见性导致的 500）——**命中 0 条**。
|
||
|
||
但在容器的原生日志里，同样的错误有 4149 + 257 条。
|
||
|
||
也就是说：**PHP 的原生错误（Warning/Fatal）从来不进结构化日志。** 如果排查时只看结构化日志（最自然的选择），就会**完全漏掉代码级缺陷**——而那正是我们当天修的三类 bug。
|
||
|
||
这意味着：同类缺陷下次还会漏检。
|
||
|
||
## 我自己的失误
|
||
|
||
治理过程中，我犯了个更不该犯的错。
|
||
|
||
为了复现"文件属主是 root"这个场景，验证脚本里写了 `file_put_contents($file, '')`——**直接清空了当天的生产日志文件**。
|
||
|
||
14527 行，归零。
|
||
|
||
影响评估：业务数据完好（数据库表都在）、结构化日志是纯诊断文件无代码消费者、容器原生日志还留有 access 记录可追溯。但**当天大半天（00:00-19:45）的请求级诊断日志，被我抹掉了**。
|
||
|
||
教训很直白：
|
||
|
||
> **破坏性测试必须在临时文件上做。** 造权限场景应该 `touch` 一个 `__test_*.log`，而不是碰当天的真实日志。
|
||
|
||
## 治理：让日志的失败可见
|
||
|
||
三处修复 + 三项治理：
|
||
|
||
**① 写入失败降级 + 告警**
|
||
主文件不可写 → 自动降级到 `.fallback.log`（目录属主正确，必定可创建）+ 同时 `error_log` 告警。模拟 root:root 场景实测：主文件空，fallback 正确落盘并告警。
|
||
|
||
**② 原生错误接入结构化日志**
|
||
注册三个钩子：`set_error_handler`（Warning/Notice → WARN）、`set_exception_handler`（未捕获异常 → ERROR + 前 8 层栈）、`register_shutdown_function`（致命错误 → ERROR）。六个 HTTP 入口全部注册。
|
||
|
||
**③ 日志健康巡检 + 定时任务**
|
||
五项检查：文件属主/权限、降级日志存在性、**当日日志量 vs 近 7 天均值（偏差 >70% 告警）**、WARN/ERROR 统计、保留体积。
|
||
|
||
第三项是核心——因为这次事故的特征正是"**文件存在，但内容几乎为空**"。**只有对比基线，才能发现这种静默丢失。**
|
||
|
||
巡检脚本首跑就检出了异常（41KB vs 期望 2887KB）——正是我自己清空日志造成的影响。机制验证有效，虽然验证方式有点丢人。
|
||
|
||
**④ 容器日志轮转**
|
||
改 compose 文件给应用容器加 `max-size: 50m / max-file: 3`，而不是改全局 daemon 配置——不用 sudo、不影响其他容器、随时可回滚。
|
||
|
||
**⑤ 慢请求阈值分级**
|
||
AI 推理端点固有耗时 5-80 秒，用 30 秒阈值；其余端点保持 1 秒。97 条慢请求里 87 条是 AI 噪音，分级后真正的慢端点立刻凸显。
|
||
|
||
## 复盘又揪出两处残留
|
||
|
||
改完做同类模式扫描，又发现两个：
|
||
|
||
1. **缓存窗口与定时任务周期不匹配**：一个探测函数默认 30 分钟，而定时任务 60 分钟一轮——虽然当前已不被调用，但"保留错误默认值 = 下次有人用时踩同坑"，改成 3600 秒
|
||
2. **只改了 chmod 没改 chown**：上轮修权限问题时我只做了 `chmod 666`（让进程能写），没做 `chown`（属主仍是 root）——巡检脚本会持续告警。**修权限要分清"访问位"和"属主"，只改一个往往不彻底。**
|
||
|
||
## 总结
|
||
|
||
1. **日志的可靠性本身需要被监控**。日志是"最后一道防线"，但它自己也会失败——而且往往失败得最安静
|
||
2. **量级异常检测 > 格式检查**。文件存在不等于日志正常，"比基线少 70%"才是真正的信号
|
||
3. **`@` 抑制错误要有代价**。降级路径 + 告警，不能只有静默
|
||
4. **原生错误必须进结构化日志**，否则排查只看一处就会系统性漏检
|
||
5. **破坏性测试绝不碰生产文件**——这条我用自己的 14527 行日志换来的
|
||
|
||
> 那天 9395 条日志消失的时候，系统一切正常——业务在跑、数据在写、用户在访问。只有日志自己知道它没在记录，而它没法告诉你。
|
||
|
||
---
|
||
|
||
*本文已脱敏，不含真实域名、IP、客户信息或系统内部标识。*
|