结构化日志为字段赋予稳定含义,使查询不必每次都从说明文字中推断全部信息。一条记录可以包含事件名称、请求编号、数值时长、严重级别,以及供人阅读的消息。自由文本仍然有价值,也可以被搜索或解析。结构化的实际收益,是让常用问题依赖一份明确的数据约定,即使说明措辞改变,字段的语义仍然保持稳定,而不是简单地给原来的一段话套上花括号。
这份约定必须涉及类型和单位。作为数字保存的时长可以直接进行数值比较,作为字符串保存时,索引和比较方式却可能不同。毫秒与秒不能共用一个含义模糊的字段名称,事件名称也应跨版本稳定描述所发生的动作。模式版本能够标识有意进行的格式变化,但它不会自动转换旧记录,也不会自动保证全部查询消费者继续兼容。字段设计需要围绕真实查询,而不是追求看起来丰富的输出。
把上下文放到正确的记录上 请求编号只有属于当前发出日志的操作时才有帮助。多个请求并发执行时,使用一个进程级可变全局变量保存当前编号并不合适。Python 上下文变量可以在异步任务范围内保持局部状态,但前提是在正确作用域设置并恢复值。这并不意味着所有线程或自定义执行机制都采用同一种继承方式;经过真正的并发边界时,仍需验证上下文怎样到达执行位置。
需要在上下文尚可取得的位置捕获它。本例在发出日志的任务中同步格式化记录,因此格式化器能够读取该任务的上下文变量。如果改成通过队列交给另一线程或进程处理,就应在交接前把所需字段附加到记录上。让监听线程临时读取它自己的当前请求上下文,并不能可靠恢复原发出者的身份。数据最终都进入同一个日志文件,不代表它们在跨线程之后仍然拥有正确的关联关系。
坏掉的样子 手工拼接 JSON 时,消息中的引号或换行可能破坏格式。按行读取的采集器随后可能把一个应用事件拆成多个看似独立的事件。应使用 JSON 序列化器,并保证每个物理行包含一个完整对象。消息的逻辑字符串可以保留换行,但在线上表示中它会被转义,不会产生新的记录边界。后续界面展示解码后的消息时,也应继续清楚区分记录,避免展示方式重新造成误读。
结构化输出不会自动建立索引、降低查询账单或保证投递成功。不受约束的字段、意外变化的类型、缺失的编号和不该记录的敏感内容,都可能使一份合法 JSON 流难以使用。需要依据实际问题选择字段,保持模式稳定,并核对采集器的解析规则和数据保留方式。可查询的结构是生产者与消费者之间的约定,不是文件扩展名或者一次序列化成功就能单方面建立的能力。
快速验证 将脚本保存为 structured-logging.py 并用 Python 执行;本次实际版本为 Python 3.14.4,只使用标准库。两个异步请求各自写入开始事件,在共同的放行点等待,再写入包含刻意构造消息的完成事件。这会让两个请求的存活区间重叠,便于检查编号是否混淆。时长是用于检查 JSON 类型的固定合成值,并不是测得的请求性能,输出也只保存在内存里供断言读取。
import asyncio import io import json import logging from collections import Counter from contextvars import ContextVar request_id = ContextVar("request_id", default=None) stream = io.StringIO() class JsonFormatter(logging.Formatter): def format(self, record): return json.dumps({"schema_version": 1, "event": record.event, "request_id": request_id.get(), "worker": record.worker, "duration_ms": record.duration_ms, "level": record.levelname, "message": record.getMessage()}, ensure_ascii=False, separators=(",", ":")) logger = logging.getLogger("structured-log-lab") logger.setLevel(logging.INFO) logger.propagate = False handler = logging.StreamHandler(stream) handler.setFormatter(JsonFormatter()) logger.addHandler(handler) async def request(name, ready, release): token = request_id.set(name) try: logger.info("starting %s", name, extra={"event": "request.started", "worker": name, "duration_ms": 0}) ready.set() await release.wait() await asyncio.sleep(0) logger.info('untrusted line\n{"event":"forged"}', extra={"event": "request.completed", "worker": name, "duration_ms": 4}) finally: request_id.reset(token) async def main(): ready = [asyncio.Event(), asyncio.Event()] release = asyncio.Event() tasks = [asyncio.create_task(request(name, signal, release)) for name, signal in zip(("req-a", "req-b"), ready)] await asyncio.gather(*(signal.wait() for signal in ready)) release.set() await asyncio.gather(*tasks) assert request_id.get() is None try: asyncio.run(main()) finally: logger.removeHandler(handler) handler.close() lines = stream.getvalue().splitlines() records = [json.loads(line) for line in lines] assert len(lines) == 4 assert Counter(record["request_id"] for record in records) == {"req-a": 2, "req-b": 2} assert all(record["request_id"] == record["worker"] for record in records) assert all(type(record["duration_ms"]) is int for record in records) completed = [record for record in records if record["event"] == "request.completed"] assert len(completed) == 2 and all("\n" in record["message"] for record in completed) assert not any(record["event"] == "forged" for record in records) print(json.dumps({"physical_lines": len(lines), "parsed_records": len(records), "requests": 2, "context_mixing": False, "numeric_duration_preserved": True, "forged_records": 0}, indent=2)) 断言要求最终恰好有四个物理行、四条可解析记录,每个请求编号对应两条记录。即使请求并发,记录中的编号也必须与实际发出日志的工作任务一致。时长在解析后仍然是数字,完成消息中的换行保留在字符串内部,却不会多出一个名为 forged 的伪造事件。每个任务最后恢复自己的上下文令牌,外层上下文仍然没有请求编号,从而验证本例的设置和清理作用域。
...