浅谈编程中的打日志(短文)

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

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

  1. 把发生的事情讲清楚,力求一目了然

    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")
    
    
  2. 几种常见的打日志的时机

    关键路径(核心函数):

    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}")
    
  3. 中文 or 英文?

    取决于,日志读者更习惯哪种语言

    如果是国内公司内部项目,中文更好、更清晰。

    如果是开源项目,面向国际的,则英文更好。

    # 不直观的
    logger.warning("Order is already cancelled, skipping delivery call: {order_id}")
    
    # 直观的
    logger.warning("订单已取消,不再呼叫配送 {order_id}")
    
  4. 善用日志级别

    日志级别,关系到事情的严重程度、应该受关注的程度

    我个人也比较喜欢,不同级别的日志、不同的颜色。

    • 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("启动时无法找到依赖目录,将退出程序!")
      
  5. 日志密度要不多不少

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

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

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

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

    [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}")
    
  6. 留下线索,方便排查问题

    不仅要把发生的事情囊括输出,还要把关键变量信息带出,尤其对于错误日志。

    留下的线索,通常是贯穿业务的核心概念, 比如订单ID、商品ID、门店编码 等。

    logger.error("订单出库失败,库存不足! {order_id} {sku_id}")
    

    我习惯把变量信息尾置, 就是放在后面

    这样不仅日志更整齐 (因为靠左对齐), 而且「不变的消息」和「变量消息」分离,方便检索:

    # 更喜欢这种变量尾置的方式
    # 原因是, 我可以按 "商品更新" 作为关键字检索
    logger.info("商品更新成功 {sku_id}")
    
    # 非尾置变量信息的方式 (不喜欢这种方式)
    logger.info("商品 {sku_id} 更新成功")
    

    此外,在心态上,当遇到一个问题,正好缺少一条关键日志线索没有埋下时, 请提交代码补上这条日志,亡羊补牢、为时未晚

  7. 打日志最好不要造成额外性能开销

    比如下方的日志,要注意 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

王超 ·
微信扫码赞赏
评论 首页 | 归档 | 算法 | 订阅