维护一个 N 年前的Python项目, 协助排查问题时发现, 原先的日志打印真真一言难尽

导致了一个问题, 同负责的运维 A 沟通, A 与其对接的甲方沟通……日志的缺失导致本来简单的问题变得复杂

如果日志打得更完备一点, 排查问题的难度不是一个的级别的

bad case

try:
    # got a data here
    # a lot of codes here
    # x = data["key"]
    # call_another_func(id, type)
    # call_another_func2(id, type, name)
except Exception:
    logger.error("error while do something")

这时候, 异常触发的时候, 日志只有

error while do something

相对于没打日志,只好了一点点, 知道有异常出现了, 问题是, 具体错误是什么?

第一次改进

try:
    # got a data here
    # a lot of codes here
    # x = data["key"]
    # call_another_func(id, type)
    # call_another_func2(id, type, name)
except Exception as error:
    logger.error("error while do something, error=%s", error)

此时报错时, 会打印

error while do something, error=App matching query does not exist

但是, 这里相对原始版本只好了一点点, 多了error message, 但是这行message并没有包含多少有利于问题排查的信息, 甚至连类型都没有, 看到了一脸懵

再次改进1

try:
    # got a data here
    # a lot of codes here
    # x = data["key"]
    # call_another_func(id, type)
    # call_another_func2(id, type, name)
except Exception as error:
    logger.exception("error while do something")

将logger.error改成logger.exception, 此时错误日志

error while do something
Traceback (most recent call last) :
  File "a.py", line 674 in call_another_func
    app = get_app(id)
  File "b.py", line 18 in get_app
    app = App.objects.get(id)
DoesNotExist: App matching query does not exist.

这时候, 有详细的错误堆栈, 可以用于追溯错误原因.

但是, 某些场景下, 看到错误堆栈并不一定能确定问题, 根据堆栈信息回去看代码, 这代码不可能有问题……

此时, 可能是数据问题(各种原因的脏数据), 或者数据被人工改动(例如直接改表数据).

如果只有以上信息, 排查问题依旧要花很多时间.

再次改进2

增加数据/业务信息等上下文, 注意不好打敏感信息

try:
    # got a data here
    # a lot of codes here
    # x = data["key"]
    # call_another_func(id, type)
    # call_another_func2(id, type, name)
except Exception as error:
    logger.exception("error while do something [id=%s, type=%s, name=%s]", id, type, name)

错误信息

error while do something[id=1, type=test, name=abc]
Traceback (most recent call last) :
  File "a.py", line 674 in call_another_func
    app = get_app(id)
  File "b.py", line 18 in get_app
    app = App.objects.get(id)
DoesNotExist: App matching query does not exist.

更好的做法

使用自定义异常, 带code/message

class BaseException(Exception):
    def __init__(self, code, message):
        self.code = code
        self.message = message
        super().__init__(f"{self.code} {self.message}")
    def __str__(self):
        return f"<ErrorCode {self.code}:({self.message})>"

class XXException(BaseException):
    .....

• 使用raise Error/CustomException替代try-except
• 在统一的地方处理错误, 例如middleware或统一调用入口, try-except依次捕获所有已知的Error和CustomException, 最后捕获通用的Exception(未知异常)

好处:

1. 底层代码逻辑更简单, 少一层嵌套, 可读性更好
2. 统一的错误声明及处理, 对于开发者及使用者都更为友好, 例如可以将错误码作为协议的一部分, 使用者根据错误码可以快速定位问题

Golang的error wrap

Go 的error wrap更为优雅, Working with Errors in Go 1.13

_, err := dosomething(type)
return fmt.Errorf("dosomething fail, type=`%s`, err=%w", type, err)

也可以看下之前 go 项目的实践: Go: 一种error wrap调用链处理方式

其他

• 不要用print替代logging
• 打很多日志等于没打
• 谨慎确定当前要打日志的level
• 尽量只在必要的地方打日志, 信息是有用的, 也是完备的, 有利于定位问题的
• 一定不要吞掉异常
• 如果使用try-except, Exception尽量精确, 打印日志尽量完备
• 如果使用try-except, 捕获的代码块尽量小, 不会出现异常的语句不要放进去. 反例: 整个函数的所有代码都在一个try-except中
• logger 本身尽量按功能/模块/业务等切分多个, 反例: 全打标准输出