第3章结构化日志

3. 结构化日志：从文本日志到JSON日志的演进

说实话，我刚开始做量化交易系统那会儿，日志全是纯文本的。就是那种「2024-01-15 09:30:00 INFO 订单已提交」的格式。看着挺清楚，对吧？但真到了排查问题的时候，你就知道有多痛苦了。

我记得有一次，凌晨两点被电话吵醒——交易系统报了个奇怪的错误。我对着几万行文本日志，用grep翻来覆去地找。想查某个订单的完整生命周期？得写一串复杂的正则表达式。想统计一下某个模块的平均耗时？得写脚本去解析字符串。那感觉，就像用螺丝刀撬钉子——能用，但真不是个事儿。

3.1 为什么需要结构化日志？

文本日志最大的问题是什么？机器读不懂。你想想看，人眼一看「INFO」就知道是信息级别，但程序要识别它，得靠正则匹配。而且不同开发者的日志格式五花八门——有人用「|」分隔，有人用「-」，有人干脆啥分隔符都不用。

结构化日志说白了，就是把日志变成机器能直接解析的格式。最常用的就是JSON。每条日志就是一个JSON对象，字段清清楚楚，程序直接就能读。

文本日志 vs JSON日志

对比维度	文本日志	JSON日志
可读性	人眼友好	机器友好
解析难度	需要正则	直接解析
字段扩展	改格式就崩	加字段无影响
查询效率	低（全文搜索）	高（按字段索引）
工具支持	少	ELK、Graylog等

3.2 字段设计规范

嗯，这里要注意。结构化日志不是随便把信息塞进JSON就完事了。字段设计得有章法。我个人习惯遵循一套核心规范，这样不管哪个模块的日志，到了ELK里都能统一处理。

下面是我在项目中沉淀下来的字段设计：

字段名	类型	说明	示例
timestamp	ISO 8601	事件发生时间，精确到毫秒	2024-01-15T09:30:00.123Z
level	string	日志级别：DEBUG/INFO/WARNING/ERROR/CRITICAL	INFO
module	string	产生日志的模块名，如 order_engine	order_engine
trace_id	string	请求追踪ID，用于串联一次完整操作	a1b2c3d4-e5f6-7890
duration_ms	int	操作耗时，单位毫秒	235
message	string	人类可读的描述信息	订单已提交至交易所
extra	object	扩展字段，放业务相关的额外数据	{"order_id": "ORD123", "price": 100.5}

我的经验：trace_id 这个字段特别重要。在微服务架构里，一次交易请求可能经过订单模块、风控模块、清算模块。没有 trace_id，你根本连不起来这些日志。我曾经就因为没加这个字段，排查一个bug花了整整两天——后来加上 trace_id，十分钟就定位到了问题。

3.3 使用 python-json-logger 输出结构化日志

Python 里实现结构化日志，最方便的就是 python-json-logger 这个库。它本质上是对标准 logging 模块的扩展，把日志格式从字符串变成了 JSON。

先安装：

pip install python-json-logger

然后看个完整的配置示例：

import logging
from pythonjsonlogger import jsonlogger
import uuid
import time

# 自定义日志处理器
logger = logging.getLogger("trading_system")
logger.setLevel(logging.DEBUG)

# 创建 JSON 格式的处理器
handler = logging.StreamHandler()
formatter = jsonlogger.JsonFormatter(
    fmt="%(timestamp)s %(level)s %(name)s %(module)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S.%fZ"
)
handler.setFormatter(formatter)
logger.addHandler(handler)

# 模拟一次交易操作
def submit_order(order_id, price, quantity):
    trace_id = str(uuid.uuid4())
    start_time = time.time()
    
    logger.info(
        "订单提交开始",
        extra={
            "trace_id": trace_id,
            "module": "order_engine",
            "order_id": order_id,
            "price": price,
            "quantity": quantity
        }
    )
    
    # 模拟处理耗时
    time.sleep(0.235)
    
    duration_ms = int((time.time() - start_time) * 1000)
    logger.info(
        "订单提交完成",
        extra={
            "trace_id": trace_id,
            "module": "order_engine",
            "duration_ms": duration_ms,
            "order_id": order_id,
            "status": "filled"
        }
    )

submit_order("ORD123", 100.5, 1000)

输出效果是这样的：

{"timestamp": "2024-01-15T09:30:00.123Z", "level": "INFO", "name": "trading_system", "module": "order_engine", "message": "订单提交开始", "trace_id": "a1b2c3d4-e5f6-7890", "order_id": "ORD123", "price": 100.5, "quantity": 1000}
{"timestamp": "2024-01-15T09:30:00.358Z", "level": "INFO", "name": "trading_system", "module": "order_engine", "message": "订单提交完成", "trace_id": "a1b2c3d4-e5f6-7890", "duration_ms": 235, "order_id": "ORD123", "status": "filled"}

看到没？每条日志都是一个完整的 JSON 对象。trace_id 把两次日志串联起来了，duration_ms 直接告诉你耗时。这在 ELK 里一搜 trace_id，整个操作链路清清楚楚。

避坑指南：我曾经犯过一个错误——在 extra 里传了非 JSON 序列化的对象（比如 datetime 对象），结果日志直接报错。所以 extra 里的值一定要确保是基础类型（str、int、float、list、dict）。如果非要传对象，记得先转成字符串。

3.4 核心逻辑：从文本到结构化的演进

下面这张图，是我自己画的。它展示了从原始文本日志到结构化日志的完整演进路径，以及每一步解决了什么问题。

3.5 进阶技巧：自定义字段与上下文管理

在实际项目中，你不可能每次都手动传 extra 参数。我一般会封装一个上下文管理器，自动注入 trace_id 和 module 信息。

import logging
from pythonjsonlogger import jsonlogger
import uuid
from contextvars import ContextVar

# 全局上下文变量
trace_id_var: ContextVar[str] = ContextVar('trace_id', default='')

class StructuredLogger:
    def __init__(self, name: str):
        self.logger = logging.getLogger(name)
        self._setup_handler()
    
    def _setup_handler(self):
        if not self.logger.handlers:
            handler = logging.StreamHandler()
            formatter = jsonlogger.JsonFormatter(
                fmt="%(timestamp)s %(level)s %(name)s %(module)s %(message)s",
                datefmt="%Y-%m-%dT%H:%M:%S.%fZ"
            )
            handler.setFormatter(formatter)
            self.logger.addHandler(handler)
    
    def _get_extra(self, **kwargs) -> dict:
        extra = {
            "trace_id": trace_id_var.get() or str(uuid.uuid4()),
            "module": self.logger.name
        }
        extra.update(kwargs)
        return extra
    
    def info(self, msg: str, **kwargs):
        self.logger.info(msg, extra=self._get_extra(**kwargs))
    
    def error(self, msg: str, **kwargs):
        self.logger.error(msg, extra=self._get_extra(**kwargs))
    
    # 其他级别同理...

# 使用示例
log = StructuredLogger("order_engine")
log.info("订单已提交", order_id="ORD456", price=99.8)

我的建议：把日志封装成工具类，团队统一使用。这样能保证所有模块的日志格式一致，字段命名统一。我见过最乱的项目——同一个系统里，有人用「orderId」，有人用「order_id」，还有人用「oid」。到了ELK里查询，那叫一个酸爽。

3.6 小结

结构化日志不是什么高深的技术，但它带来的收益是实实在在的。从文本到JSON，你付出的只是改一下日志格式的代价，换来的却是整个监控体系的基石。

记住几个关键点：字段设计要规范、trace_id 必须加、duration_ms 是性能监控的命根子。把这些做好了，后续的日志分析、告警、链路追踪，都会轻松很多。

公众号:蓝海资料掘金营，微信deep3321

📚 课程目录

3. 结构化日志：从文本日志到JSON日志的演进

3.1 为什么需要结构化日志？

3.2 字段设计规范

3.3 使用 python-json-logger 输出结构化日志

3.4 核心逻辑：从文本到结构化的演进

3.5 进阶技巧：自定义字段与上下文管理

3.6 小结