日志明明已经写了,程序崩溃时最后几行为什么还是不见了?
线上服务在处理请求时打印了三条日志:
1 | request accepted |
随后进程崩溃,日志文件却只留下第一条。开发者第一反应通常是“日志库有 bug”,但异步日志中的“写了”可能只表示业务线程把字符串放进内存队列,既不代表日志线程已经消费,也不代表用户态缓冲已经刷新,更不代表数据已经持久化到存储设备。
本文从一个可运行的同步日志器开始,解释日志级别、稳定字段和 std::source_location;再实现一个有界队列的 C++20 异步日志器,重点处理初始化顺序、背压、正常关闭和丢弃统计。最后讨论 request ID、结构化日志、轮转、敏感信息以及 spdlog 的工程边界。目标不是手写一个功能齐全的日志库,而是理解成熟日志库必须替你解决哪些问题。
1. 当程序不在眼前时,日志需要回答什么?
日志最核心的价值是:
1 | 当程序不在你眼前、不能打断点、问题难以复现时, |
服务端项目里,日志通常用于还原某次请求的入口、关键分支、上游调用、错误原因和退出结果。但日志并不是可观测性的全部:
- 记录请求入口和出口
- 定位错误路径
- 记录上游调用耗时
- 追踪异步任务状态
- 排查连接断开、超时、限流
- 压测时分析 p95 / p99 异常点
- 复盘用户一次完整请求链路
| 手段 | 擅长回答的问题 | 不适合替代什么 |
|---|---|---|
| 日志 | request_id=abc 为什么失败? |
整体趋势和高效实时告警 |
| 指标 | 最近五分钟错误率、p99 是否异常? | 单次请求的详细上下文 |
| Trace | 一次跨服务调用经过哪些节点? | 所有业务字段和长期审计记录 |
| Profiling | CPU 时间、锁竞争、分配热点在哪里? | 业务错误原因 |
| 测试 | 已知输入是否符合预期? | 线上某次真实事件的复盘 |
一句话概括:
1 | 测试保证行为,指标发现趋势,日志解释细节。 |
这也解释了为什么不能靠“多打点日志”解决所有问题:日志越多,I/O、存储、查询成本和敏感信息风险越高,还可能反过来放大服务尾延迟。
2. 日志级别
常见日志级别:
| 级别 | 用途 | 示例 |
|---|---|---|
| TRACE | 极细粒度调试,默认关闭 | 每个包的解析细节 |
| DEBUG | 本地调试信息 | 路由命中、内部状态 |
| INFO | 正常关键事件 | 服务启动、请求完成、任务完成 |
| WARN | 可恢复异常 | 上游慢、重试、限流 |
| ERROR | 当前操作失败 | 上游超时、数据库写失败 |
| FATAL | 进程无法继续 | 配置缺失、端口绑定失败 |
建议:
- 正常请求完成用
INFO - 用户输入错误通常不是
ERROR - 上游失败、数据库失败才更适合
ERROR - 高频路径不要打大量
DEBUG FATAL表达进程无法继续,但不同日志库是否自动终止并不一致;退出行为要由应用明确控制
日志级别是运维契约,不是情绪强度。把每个 404 都记为 ERROR 会淹没真正故障;把数据库写失败记成 INFO,又会让告警和排查失去入口。团队应为每一级定义稳定语义,并结合采样和告警规则评审。
3. 一条好日志应该包含什么
一条服务端日志至少要能回答:
1 | 谁在什么时候对哪个接口做了什么,结果如何,耗时多少,失败原因是什么。 |
推荐字段:
| 字段 | 说明 |
|---|---|
| timestamp | 时间 |
| level | 日志级别 |
| service | 服务名 |
| request_id | 请求 ID |
| user_id | 用户 ID,没有就为空 |
| method | HTTP 方法 |
| path | 请求路径 |
| status | 响应状态码 |
| duration_ms | 耗时 |
| error_code | 业务错误码 |
| upstream | 上游服务名 |
| file / line | 代码位置 |
示例:
1 | 2026-05-12T10:01:03.123Z INFO service=gateway request_id=9f32 method=POST path=/v1/chat status=200 duration_ms=182 upstream=rag_api |
4. 不建议这样打日志
4.1 只写一句失败
1 | LOG_ERROR << "failed"; |
问题:不知道谁失败、为什么失败、哪个请求失败。
更好:
1 | LOG_ERROR << "request_id=" << requestId |
4.2 打印敏感信息
不要直接打印:
- password
- token
- API key
- Authorization header
- 完整身份证 / 手机号
- 私有文档全文
认证秘密最好完全不进入日志,而不是“只露出首尾几位”。例如只记录请求是否携带认证信息以及认证结果:
1 | LOG_WARN << "event=authentication_failed" |
用户标识、IP 和文件名同样可能属于个人信息,应根据用途做假名化、访问控制和保留期限设计。脱敏规则不是日志函数里的临时字符串技巧,而是数据治理要求。
4.3 高频循环里打 INFO
比如每个 token、每个 UDP 包都打 INFO,压测时日志会反过来拖慢系统。
建议:
- 高频细节用
TRACE/DEBUG - 默认关闭
- 或按采样率打印
5. 如何写出一个可运行的同步日志器?
先用同步版本建立语义:调用返回前,当前线程已经把一整行交给输出流并执行 flush()。示例使用 C++20 的 std::source_location 自动捕获调用位置,避免依赖 <format> 的实现差异。
1 |
|
编译运行:
1 | clang++ -std=c++20 -O2 -Wall -Wextra -Wpedantic \ |
输出中的时间戳和源码行号会随运行变化,结构类似:
1 | timestamp_ms=1770000000000 level=INFO file=sync_logger.cpp line=61 message="server started" |
互斥锁保证多个线程的一行内容不会相互穿插;source_location 作为默认实参求值时记录调用点,而不是 log() 函数定义的位置。这里每行都 flush,换来了清晰语义,也让业务线程承担格式化、锁竞争和输出等待。
这个最小示例只传入可信的固定消息;如果 message 或字段来自用户输入,必须先按第 9 节转义,否则换行和引号会破坏一行一事件的格式。
同步日志器优点:
- 简单
- 不容易丢日志
- 相比异步队列,正常错误退出前更容易看到最后日志
缺点:
- 多线程竞争锁
- 写磁盘慢时阻塞业务线程
- 高频日志影响延迟
即便 std::clog.flush() 返回,也通常只表示 C++ 流缓冲已经向下层提交,不等于数据已经物理落盘。SIGKILL、内核崩溃、断电和存储故障仍可能丢失数据;若审计记录要求持久性,需要专门的事务或可靠事件系统,不能把普通日志文件当数据库。
6. RAII 日志行
为了写出类似流式语法:
1 | LOG_INFO << "request_id=" << id << " status=" << status; |
可以用 RAII:构造收集内容,析构时写出。
1 |
|
使用:
1 | LOG_INFO << "server started port=" << 8080; |
注意:
- 宏里使用临时对象,表达式结束时析构
- 不要把
LogLine存起来跨线程使用 - 真实项目要处理日志级别过滤,否则即使关闭 DEBUG 也可能构造字符串
- 析构函数不能向外抛异常;生产实现还应通过错误回调或指标暴露日志写入失败
7. 关闭 DEBUG 后,怎样避免仍然构造昂贵字符串?
1 |
|
只在 logger 内部丢弃消息已经太晚,调用方可能完成了序列化和字符串拼接。一个不依赖脆弱 if/else 宏的最小做法,是把消息构造延迟到 lambda 中:
1 | template <class MessageBuilder> |
使用:
1 | logIfEnabled(logger, config, LogLevel::Debug, [&] { |
当 DEBUG 关闭时,lambda 不执行,std::to_string 和拼接都不会发生。std::atomic<LogLevel> 让运行时调整级别与并发读取之间没有数据竞争;这里不需要跨对象同步,所以 relaxed 顺序足够。成熟库通常还提供编译期级别裁剪,能让低级别日志连分支都不进入。
8. 怎样实现一个不会在线程启动时就产生竞态的异步日志器?
异步日志的结构:
1 | 业务线程 |
如果输出到普通文件,一条消息大致经过:
1 | 业务线程 |
不同失败发生在不同位置。正常关闭可以排空进程内队列;用户态 flush 可以把流缓冲交给操作系统;要讨论断电持久性,还需要操作系统和文件系统级同步语义。普通业务日志通常不会为每行执行昂贵的持久化同步,因此必须明确可接受的数据丢失窗口。
原稿中最容易忽略的坑,是在成员初始化列表里直接启动 worker_。C++ 成员按声明顺序初始化,线程一旦启动就可能访问排在它后面、尚未初始化的状态。安全做法是先构造全部成员并检查文件,再在构造函数体中启动线程。
下面的 C++20 最小实现采用有界队列,队列满时丢弃最新消息,并把丢弃量暴露出来:
1 |
|
1 | clang++ -std=c++20 -O2 -Wall -Wextra -Wpedantic -pthread \ |
正常运行时,统计应为 dropped=0 write_errors=0,文件中能看到两行日志。shutdown() 先在锁内停止接收,再通知工作线程;工作线程把队列交换到局部 batch,释放锁后执行慢 I/O,因此生产者不会在整个文件写入期间持有队列锁。当队列为空且 stopping_ 为真时,线程退出,调用方 join 后才继续销毁文件流。
log() 返回 false 表示消息未被接受:可能是队列已满,也可能已经进入关闭阶段。真实接口可以把两种原因拆成枚举;无论如何,调用方或独立指标必须能观察失败,不能默默假设消息已经记录。
异步日志必须考虑:
- 队列满了怎么办:丢弃、阻塞、降级同步?
- 进程崩溃时允许丢多少条、多少毫秒的数据
- 可控 FATAL 路径是否需要同步应急输出并执行有界等待
- 日志线程退出时要刷完队列
- 日志量太大时要限速或采样
这个实现只保证正常调用 shutdown() 时排空已接收队列。std::terminate、段错误、abort()、SIGKILL、容器强制终止或断电都可能绕过析构;也不要从 POSIX 信号处理函数调用普通 C++ logger,因为锁、分配器、iostream 和大多数日志库 API 都不是 async-signal-safe。崩溃转储、外部进程采集和同步应急通道是另一层设计。
9. 结构化日志
普通文本日志方便人看,但机器分析更喜欢结构化字段。
推荐风格:
1 | level=INFO service=gateway request_id=abc method=POST path=/v1/chat status=200 duration_ms=183 |
或者 JSON Lines:
1 | {"level":"INFO","service":"gateway","request_id":"abc","method":"POST","path":"/v1/chat","status":200,"duration_ms":183} |
简单 key-value 编码:
1 |
|
使用:
1 | LOG_INFO << kv("request_id", requestId) |
换行、回车和制表符必须转义,否则用户提供的 path 或 header 可以伪造第二条日志,这叫日志注入(log injection)。上面的 key 假设是代码中写死的稳定字段名;若要输出严格 JSON,应使用项目已有的 JSON 序列化库,不要继续扩展手写转义器。
10. request id
跨服务链路一定要有 request id:
1 | Gateway log request_id=abc |
请求 ID 来自 header 时仍是不可信输入,至少限制长度和字符集:
1 |
|
转发给上游:
1 | upstreamReq->addHeader("x-request-id", requestId); |
返回给客户端:
1 | resp->addHeader("x-request-id", requestId); |
在可信网关内部可以透传同一个 ID;面向公网的边缘服务还应考虑客户端故意复用 ID 的情况。需要严格分布式追踪时,应采用团队统一的 trace context 规范,而不是让每个服务各自发明 header。
11. 请求访问日志
Gateway 建议每个请求完成时打一条访问日志:
1 | class RequestTimer { |
墙上时间(system_clock)用于回答事件发生在什么时候,单调时钟(steady_clock)用于测耗时。系统校时可能让墙上时间跳变,因此不能用两个 UTC 时间戳简单相减来计算可靠延迟。完整源文件还需包含 <chrono> 和 <cstdint>。
示例:
1 | void logAccess( |
访问日志通常应在响应真正完成或连接确定终止时记录,否则异步响应可能只记录“开始处理”,却没有最终状态和耗时。客户端 IP 可能属于个人信息;query、header 和请求体还可能包含秘密,不能为了排障无差别写入。
12. 日志和指标的边界
日志适合查一次具体请求:
1 | request_id=abc 为什么失败? |
指标适合看整体趋势:
1 | 过去 5 分钟 502 比例是否升高? |
不要试图只靠日志做监控,否则:
- 成本高
- 查询慢
- 不适合实时告警
建议:
| 场景 | 用日志 | 用指标 |
|---|---|---|
| 某次请求失败原因 | 是 | 辅助 |
| 错误率趋势 | 辅助 | 是 |
| 慢请求定位 | 是 | 是 |
| 任务状态变化 | 是 | 是 |
| token 逐个输出 | 通常否 | 可计数 |
尤其不要只靠日志报告“日志写入失败”,因为故障通道就是日志本身。队列深度、dropped_logs_total、log_write_errors_total 和最近一次成功写入时间应通过独立指标或健康检查暴露。request_id、用户 ID 等高基数字段适合日志和 trace,不应直接作为时序指标标签,否则会造成指标系统基数爆炸。
13. 日志滚动
长期运行服务不能只写一个无限增长文件。
常见策略:
- 按大小滚动:超过 100MB 切新文件
- 按时间滚动:每天一个文件
- 保留最近 N 天
- 压缩旧日志
核心流程看起来简单:
1 | 编码一整行 |
真正困难的是重启后如何恢复当前大小、文件名如何避免覆盖、多进程是否同时写同一文件、rename 失败怎么办、超长单行如何处理、磁盘满时采用什么降级策略,以及压缩/删除线程会不会和写线程竞争。几十行示例无法可靠覆盖这些情况。
真实项目优先使用成熟库,比如:
- spdlog
- glog
- Boost.Log
- Drogon 自带日志能力
14. 为什么理解原理后仍应优先使用 spdlog?
轮转、格式化、sink 组合和异步队列都有大量边界,业务项目通常应复用已有日志库。下面以 spdlog 1.17.0 API 为参照;如果项目锁定其他版本,应以依赖文件和对应版本文档为准,不要为了笔记擅自升级。
同步轮转示例:
1 |
|
异步轮转示例:
1 |
|
注意:
overrun_oldest表示队列满时丢旧日志- 如果不能丢日志,可以改为
block,但业务线程会承受背压,必须压测尾延迟 - 日志目录需要可创建、可写,并监控磁盘空间和 sink 错误
- 所有生产者停止后,正常退出路径应调用
spdlog::shutdown()清理全局线程池
必须特别区分“请求 flush”和“确认持久化”。在 spdlog 1.x 的异步 logger 中,flush() 本身走异步队列,调用返回不能简单理解为此前消息已经同步落盘;即使 sink 完成用户态 flush,也不是 fsync 级别的断电保证。对于应用可控的致命错误,可以先走独立同步应急通道,再执行有时间上限的正常关闭;对于段错误或信号上下文,不要调用非 async-signal-safe 的日志 API。
15. 已发布项目的观测边界与日志清单
本节于 2026-10-03 核对。下列字段是排障时需要关联的信息,不表示每个字段已由当前实现作为独立日志输出。
15.1 RAG:请求、任务、消息与 Trace
Gateway、FastAPI 和 Celery 日志需要通过请求、文档、任务、会话及消息标识关联。检索使用 LanceDB 召回、MySQL 正文回表和 CrossEncoder 重排;Agent 将 run、step、工具调用与结果记录到 Trace。工具返回时可能聚合提供多个检索阶段信息,不能凭前端节点变化编造独立实时耗时。
1 | request_id / session_id / user_message_id |
普通 Chat 续传复用 user_message_id,Agent 复用同一 session 和 trace_id;终止事件要在回答与 citations 落库后发送。续传状态默认在完成后保留 15 分钟,存在于进程内,不能把数据库中的最终消息等同于持久化了全部 SSE 事件。
15.2 VisionTrack:结构化日志与指标分别看
VisionTrack 的上传日志采用字段白名单,关联 request ID、route、stream ID、状态码与性能计数,不记录上传文件名或原始异常文本;实时流日志不记录源地址。
timing、metrics、high_low_diagnostics用于单次响应诊断。/metrics提供 Prometheus 流、共享调度器、上传任务池和门禁指标。- 每路
detection/endSSE 使用递增 ID,最多缓存 256 条;游标无效返回 error,进程重启不能恢复缓存。 - 上传视频一次性返回 JSON,没有持久化 job 或续算语义;日志中的任务池运行数不代表已创建可查询任务。
/health与/ready的成功不能证明摄像头连通、检测精度或多路吞吐合格。
对比实验要同时保留刷新率、排队、过期、RSS 和清理结果。SSE Trace、日志、指标各有计时边界;不要把模型均值耗时、整段视频 FPS 和实时流检测刷新率混为同一个数字。
参考:RAG 观测说明、VisionTrack 日志与失败语义。
16. UDP 权威同步项目日志清单
建议记录:
1 | match_id |
注意:
- 不要每个 tick 默认打 INFO
- 压测时可以聚合后定期输出
- hash mismatch 时要打详细状态
示例:
1 | LOG_WARN << "type=hash_mismatch" |
17. 常见误区
17.1 误区:日志只是顺手写文件,不会影响主流程
同步日志会直接阻塞业务线程;异步日志也要格式化、分配、竞争队列并消耗磁盘带宽。高频请求里打太多日志会影响 p99。应使用级别过滤、采样、聚合和压测验证,而不是凭“异步”二字假设没有成本。
17.2 误区:错误堆栈足够,不需要 request ID
错误堆栈说明代码位置,却无法自动指出它属于哪个用户请求和哪次上游重试。正确做法是在入口生成或验证 ID,并在异步任务、上游请求和最终响应中持续传递。
17.3 误区:只在异常处记录就够了
没有少量正常完成日志,就无法判断请求是否根本没有进入服务,还是在某一步静默退出。入口不必和出口各打一条 INFO;通常一条包含最终状态和耗时的访问日志更紧凑。
17.4 误区:内部日志可以记录完整请求,反正用户看不到
日志往往会被集中采集、长期保存并开放给更多运维人员,泄露面可能比业务数据库更大。认证信息、请求体和私有文档默认不记录,确有审计需求时也要做字段级策略、权限和保留期限控制。
17.5 误区:调用了异步 log() 就算记录成功
调用成功可能只表示进入内存队列;队列满、进程崩溃、磁盘写失败都会让消息消失。要定义 overflow policy,并通过独立指标暴露丢弃、队列深度和写入错误。
17.6 误区:字段名只是文本,随时改也没关系
日志字段实际上是下游查询和告警依赖的数据契约。今天写 requestId、明天写 request_id 会破坏仪表盘和检索。字段变更应像 API 变更一样评审,必要时并行输出过渡版本。
18. 什么时候用同步日志,什么时候用异步日志?
| 场景 | 更合适的起点 | 原因 |
|---|---|---|
| CLI、小工具、低频管理进程 | 同步日志 | 实现和退出语义简单,性能通常足够 |
| 高并发服务的一般访问日志 | 有界异步日志 | 把大部分文件 I/O 移出请求线程,但必须定义背压 |
| 启动失败、配置错误 | 同步 stderr | 异步线程池和文件系统可能尚未就绪 |
| 可控的致命业务错误 | 同步应急输出 + 有界关闭 | 尽量保留上下文,但不能无限等待 |
| 审计、计费、资金变更 | 事务事件或可靠消息系统 | 普通日志不提供所需的持久性和幂等保证 |
| POSIX 崩溃信号处理函数 | 极小的 async-signal-safe 通道 | 普通 logger 的锁、分配和格式化都不安全 |
同步与异步不是“慢”和“快”的简单标签。低频服务使用同步日志往往更可靠、更容易维护;只有压测证明日志 I/O 是明显成本时,才值得承担异步队列的丢失策略、线程生命周期和监控复杂度。
19. 总结:真正要定义的是日志交付语义
回到开头,崩溃前最后几行消失,往往是因为团队把“调用了日志 API”“进入异步队列”“写入内核缓存”和“持久化到设备”混成了一件事。一个可维护的日志系统至少要明确:
- 同步与异步路径分别保证到哪一层,哪些退出方式可能丢数据。
- 有界队列满时阻塞、丢新还是覆盖旧,以及如何独立统计损失。
- 字段、级别、request ID 和时间语义必须稳定,耗时使用单调时钟。
- 用户输入要防日志注入,秘密和个人信息要在进入日志前治理。
- 轮转、异步线程池和 sink 错误优先交给成熟库,但仍要核对版本语义。
可以立即落地的一条建议是:人为把异步队列压满并执行一次正常关闭测试,确认服务的背压策略、dropped_logs_total、文件内容和退出时限都符合预期。没有演练过的“不会丢日志”,通常只是一种假设。
20. 参考
- spdlog 1.17.0 Releases:https://github.com/gabime/spdlog/releases
- spdlog README:https://github.com/gabime/spdlog
- spdlog 异步 flush 语义讨论:https://github.com/gabime/spdlog/discussions/3046
- Drogon logging:https://github.com/drogonframework/drogon/wiki
std::source_location:https://en.cppreference.com/w/cpp/utility/source_location