V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
The Go Programming Language
http://golang.org/
Go Playground
Go Projects
Revel Web Framework
XdpCs
V2EX  ›  Go 编程语言

如何更好的打印日志

  •  
  •   XdpCs ·
    XdpCs · 168 天前 · 1475 次点击
    这是一个创建于 168 天前的主题,其中的信息可能已经有所发展或是发生改变。

    在日常的生产过程中,会出现一些 bug ,导致很难查找问题的所在

    想问问各位前辈 有什么打印日志的标准

    是否能给予一些例子

    谢谢各位大佬

    6 条回复    2024-09-03 19:47:17 +08:00
    vczyh
        1
    vczyh  
       168 天前   ❤️ 1
    首先分离责任边界,对外提供的接口的入参都打印出来,出现错误的话必须打印出来,可以在出现错误的时候打印,也可以在最高层统一打印,永远不要直接吞掉错误。
    kuanat
        2
    kuanat  
       167 天前   ❤️ 2
    以打印日志的方式来 debug ,在开发阶段和生产阶段是有区别的。正好前两天我在 https://v2ex.com/t/1038327 这个帖子里有个回复,可以参考一下。

    以我的经验来看,日志 debug 这个话题表面上看是个技术问题,然而我更倾向于把它们定义为工程问题。把问题聚焦在代码怎么写上面很难形成有效的思路,想明白动机和目标之间的联系,才能得出如何正确实现的方法。



    我就针对生产环境日志打印做个补充,这里就拿一般 go 服务器后端的场景来说明。

    - 日志采集的方式

    一般要么写本地文件,然后有 agent 负责汇总到日志服务器。要么直接根据配置向日志数据库来写。也就是说一般生产环境里日志排错主要靠数据库查询。

    - 日志生成方式

    上面帖子里有提到,生产环境的日志是“共享”的,也就是说日志主数据库很可能是全链路的信息都在,而某个 go 模块的信息只是一部分。这个主日志里面,多数时间理论上只包含业务信息,无法用于 debug 。

    所以在我接触的项目里,会构建 release/debug 两个版本,线上部署 release 版本。当出现故障需要排错的时候,切一部分流量进入 debug 版本,debug 版本单独输出详细日志。这个日志包含程序运行信息,stack trace 等等。

    - 日志记录的内容

    生产环境排错主要是回答两个问题:首先是判断是不是该模块的错误,其次才是为什么出错。利用日志作为 debug 手段属于某种意义上的“异步”,感到困难的主要原因是,这个异步行为很难在本地开发工作流中复现。

    如果能方便且顺利地在本地复现,困难可能就解决了一半。为了达到复现的目的,需要 debug 级日志中一定要包含进入本模块的输入,以及离开本模块的输出。



    回到代码的层面,要做的就是把上面的思路具体化。

    - 构建测试用例

    当拿到输入和输出的时候,就可以在本地开发流程构建测试用例了。考虑到 go 实现的功能模块会涉及其他模块的调用,那就需要以 mock 的方式,直接引入其他模块的输入输出结果。这里就能看出来,debug 级别的日志,一定要包含和其他模块交互的输入输出。

    这里顺便一提,mock 实现本地测试应该是开发流程中就要做的。

    - 日志可读性

    如果 go 实现的模块比较复杂,要记录各种输入输出就需要一定的组织规范,这就是你提到的问题。如果直接回答如何做,可能很难帮助你解决问题。

    由于异常分析要在请求层面上,所以要求整个系统必须有统一的 traceID 之类的标志,不然就会可能拿着不匹配的输入与输出做调试。多数时候这个 traceID 是以中间件控制,或者在各个模块之间显式传递,无论哪种实现方式,都一定要有。

    大的层面上,一定要记录 stack trace 即调用栈的回溯信息。它的作用是帮助你快速定位出问题的子模块,我个人比较倾向使用的方式类似于 error wrapping 的方式,可以参考 https://go.dev/blog/go1.13-errors 这篇文章。

    这样对于错误,可以输出类似于 `调用方法 A ,入参 XXX : 调用方法 B ,入参 XXX : ...` 这样形式的字符串,冒号用于分隔。怎么记录不重要,标准一致即可。如果有需要,可以本地额外做一个更加 verbose 的 debug 版本,利用反射机制输出调用代码的行数等等。(这个事情主要是 API 接口相关的,模块内部流程的底层错误建议 wrap ,到达模块边界只返回定义好的 sentinel 错误。)

    对于非错误的情况,一般在每个调用的入口和出口,根据调用的状态来输出不同等级的信息,比如某个方法调用的入口,输出 log.Info("XXX"),如果是走的正常分支,就在出口处再记录 log.Info("XXX"),如果走的是异常分支,可以在出口处记录 log.Warning("XXX")。这样最终会形成类似

    ```
    INFO: 调用 A 开始
    INFO: > 调用 B 开始
    INFO: >> 调用 C 开始
    INFO: << 调用 C 分支 C1
    WARN: < 调用 B 分支 B2
    INFO: 调用 A 结束
    ```

    这个样子的日志记录,可以肉眼观察也可以利用文本工具来筛选。

    这个日志的主要作用是帮助你确定异常发生时,对应的逻辑流程是什么,免去了你动态调试跟踪的麻烦。即便后续需要动态调试,也可以很准确地在目标位置下断点。

    - 其他细节

    我暂时能想起来一部分,如果以后想起来再补充。

    日志层面一定要使用结构化的方式来记录,这样无论是写入数据库,还是查询筛选都会方便很多。

    代码层面不要忽略任何错误,所有的错误都要有相应的处理(忽略也是一种处理,但一定要有对忽略错误这个行为的日志记录)。

    模块内部对于所有外部输入都做 mock ,以提高测试覆盖率,方便后期 debug 。

    这个事情的终极目标就是,出问题的时候,日志数据库筛一下就知道业务层面上是否有异常。有的话,立即切 debug 版本就能复现输入输出。拿到输入输出直接扔给本地 mock 版本,跑一下流程就知道是自己模块的问题,还是涉及其他交互模块的问题。如果确定是自己的问题,看 verbose 日志快速确定是哪个方法哪一行的错误。

    写日志本质上就是以上述思路为目标做准备。
    gvison
        3
    gvison  
       166 天前
    把请求经过的整条链路日志打印出来,通过 trace_id 或 request_id 把入参信息、返回信息、错误信息串联起来,通过 id 过滤可以查看整条请求链路日志信息,排查 bug 挺方便。可以参考这里封装的 gin 中间件 https://github.com/zhufuyi/sponge/blob/main/pkg/gin/middleware/logging.go
    qloog
        4
    qloog  
       140 天前
    wusu
        5
    wusu  
       133 天前
    @qloog 正则可以定义成全局变量,提升一点性能
    Charlie17Li
        6
    Charlie17Li  
       66 天前 via iPhone
    @vczyh 一直很纠结,是在出错的地方打印,还是上层打印。在出错的地方打印,有时候链不知道调用链路,在上层打印,链路一长,定位起来也不够直观
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   2758 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 23ms · UTC 01:54 · PVG 09:54 · LAX 17:54 · JFK 20:54
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.