浅谈编程中的打日志（短文）

一篇短文谈下我对编程中「打日志」这个事的看法和感悟。

一家之言，欢迎文末评论区交流。

把发生的事情讲清楚，力求一目了然。

logger.info("订单已创建 {order_id}")
logger.error("订单创建失败, 库存不足！{order_id} sku={sku_id}")

拒绝下面这样的日志，因为单纯从日志上看，不知道发生了什么：

logger.info(locals())
logger.info(obj)

除了讲发生了什么，最好也讲下将要如何处理。

我常用以下几种句式，注意看尾部单词：

# 跳过一件事的处理
logger.warning("发现已经存在一张配送单，命中幂等，不再新建, skipping")

# 丢弃无需处理的任务
logger.warning("收到消息过期太久，不再处理, dropping")

# 异常可以忽略，不影响后续处理
logger.warning("消息推送失败, 忽略此错误, ignored")

# 遇到异常，无法继续处理
logger.error("无法继续处理此任务, aborting")

几种常见的打日志的时机：

关键路径（核心函数）：

logger.info("用户支付成功, 支付流水号: {payment_id}")

状态改变时:

logger.info("订单取消成功: {order_id} {reason}")

逻辑分叉时:

if exist(file):
    logger.info("成功加载配置文件 {file}")
else:
    logger.warning("未找到文件, 将采用默认配置文件 {file}")

错误发生时:

try:
    push(message)
except Exception as e:
    logger.exception("推送消息失败! {message} => {e}")

中文 or 英文?
取决于，日志读者更习惯哪种语言。
如果是国内公司内部项目，中文更好、更清晰。
如果是开源项目，面向国际的，则英文更好。
```
# 不直观的
logger.warning("Order is already cancelled, skipping delivery call: {order_id}")

# 直观的
logger.warning("订单已取消，不再呼叫配送 {order_id}")
```
善用日志级别
日志级别，关系到事情的严重程度、应该受关注的程度。
我个人也比较喜欢，不同级别的日志、不同的颜色。
- info 表示事情一切正常：
```
 logger.info("门店创建成功 {shop_id} {shop_name}")
```
- warning 适合一些软错误。
  比如，可预判的错误、用户或业务级别的错误、可以降级的异常。
  相比于真正严重的错误而言，它们并不特别需要研发关注。
```
 # 用户/业务级别的错误
 logger.warning("商品不存在 {sku_name}")

 # 可以预判的错误
 logger.warning("订单已取消，不允许操作 {order_id}")

 # 可以降级的问题
 logger.warning("未找到最佳匹配方案，将采用默认配置...")
```
- error 表示需要关注的错误发生。
  比如系统级别的、未知的错误，需要开发者特别关注。
```
 logger.error("未知错误！数据库访问 => {error}")
```
- fatal / critical 表示严重错误发生，足以影响进程终止。
```
logger.fatal("启动时无法找到依赖目录，将退出程序！")
```

日志密度要不多不少

打日志太少，容易丢失排查线索。

打日志太多, 容易淹没重点信息。

想象一下，开发期调试的时候，一个事件的触发，输出一大坨日志，非常影响流程跟进，也影响日志的整体美观。

日志的密度正好的时候，人工跟进输出会有非常愉快的调试体验：

[server] INFO 2023-06-25 22:33:05 加载配置文件成功 ./config.yaml
[server] INFO 2023-06-25 22:33:06 启动 TCP 服务成功 tcp://127.0.0.1:8000/
[server] INFO 2023-06-25 22:35:10 建立新连接, 来自: 127.0.0.1:62283
[server] INFO 2023-06-25 22:36:30 收到新消息: 订单开始配送 order_id=235728122
[server] INFO 2023-06-25 22:36:31 收到新消息: 订单配送成功 order_id=235728122
[server] WARN 2023-06-25 22:36:31 收到新消息: 未知消息类型，ignored
[server] ERRO 2023-06-25 22:36:31 连接第三方服务错误: Broken pipe.
[server] INFO 2023-06-25 22:36:50 连接断开，从连接池移除: 127.0.0.1:62283

一种比较平衡的策略是，遭遇错误则打一次、正向路径只打一次。

def make_order():
    if out_of_stock:
         # 遭遇错误则打一次日志
         logger.warning("库存不足，下单失败; 库存情况: {required} vs {stock}")
         return

    if balance_insufficient:
         # 遭遇错误则打一次日志
         logger.warning("用户余额不足，下单失败 {user_id}")
         return

    # 正向的 info 日志，只需在真正成功时打印一次即可
    # 正向路径中间无需打印；如果需要可选择 debug 级别
    logger.info("下单成功 {order_id}")

留下线索，方便排查问题
不仅要把发生的事情囊括输出，还要把关键变量信息带出，尤其对于错误日志。
留下的线索，通常是贯穿业务的核心概念，比如订单ID、商品ID、门店编码等。
```
logger.error("订单出库失败，库存不足！ {order_id} {sku_id}")
```
我习惯把变量信息尾置, 就是放在后面。
这样不仅日志更整齐 (因为靠左对齐)，而且「不变的消息」和「变量消息」分离，方便检索：
```
# 更喜欢这种变量尾置的方式
# 原因是, 我可以按 "商品更新" 作为关键字检索
logger.info("商品更新成功 {sku_id}")

# 非尾置变量信息的方式 (不喜欢这种方式)
logger.info("商品 {sku_id} 更新成功")
```
此外，在心态上，当遇到一个问题，正好缺少一条关键日志线索没有埋下时，请提交代码补上这条日志，亡羊补牢、为时未晚。
打日志最好不要造成额外性能开销
比如下方的日志，要注意 format_address 函数的耗时，不应在其中做复杂计算，更不要包含 IO 过程。
```
def format_address(addr):
    info = get_addr_detail_from_db(addr.id)
    ...

logger.warning("收货地址填写有误 {format_address(addr)}")
```
仅仅为了打日志的话，不应影响到程序用户的功能体验。
留下线索，并不必就地展开线索。
```
logger.warning("收货地址填写有误 {addr_id}")
```

（完）

相关阅读: 浅谈编程中的命名（短文）

本文原始链接地址： https://writings.sh/post/logging