对程序来说,良好的日志风格能够极大的降低排错的成本,增强程序的健壮性与可运维性,但大多数开发同学并没有将日志的重要性提的和代码本身一样高,本文讨论我个人记录日志的一些最佳实践
基本原则
将日志作为程序的第二个UI
软件的第一UI当然是使用方或API调用方,而日志作为第二UI,用于开发、运维、合作方进行线上应用状态的检测与问题排查。日志的质量是代码质量的一部分。
写日志时,考虑看日志的人无法访问代码
通常来说,看日志的角色不仅仅是开发代码的人员,包括线上值班人员、售后人员、其他合作方系统的人员,可能都需要依赖日志排查问题。今天的IT系统日志更容易收集后中心化,使得不同角色可以更容易访问日志。对于API,尤其是涉及其他多个子系统调用的复杂API,良好的日志可以为调用方、线上值班提供丰富的问题排查依据,在代码中打印日志时要考虑无法访问代码的角色。
日志的主要用户是Human,次要用户是机器,所以可读性很重要
可读性包含的内容很多,下面会解释一些原则,但最基本的原则是缩进、空格等需要让阅读者易于阅读。同时日志格式也保证易于模式化解析(简单的字符串匹配,而不是复杂的正则)
考虑日志的目的是什么
日志的目的不仅仅是线上Debug,也可以是记录性能或是收集后做数据分析,考虑日志在系统的目的,写日志时具备一定针对性。
最佳实践
为日志添加上下文
非常General的日志是非常糟糕的,不仅无助于定位问题,更容易造成混淆。比如下面这个日志:
2021-11-30 16:44:52,725 [WARN] Connection failed!
无法定位是哪段代码,连接什么失败,也不知道失败的参数是什么,更好的日志格式如下:
类似问题还比如:
//don't do that
java.lang.IndexOutOfBoundsException//do that
IndexOutOfBoundsException: index 25 is greater than list size 20.
对于日志,尽量避免太general的日志,记得我们的原则,知道我们的第二个UI的目标受众是谁,看日志的人大多数可能无法访问代码。
端到端的日志&并发线程日志问题
每个请求都需要有一个唯一标识符与之对应,通常是一个GUID,主要用于两个用途
1.在不同系统或微服务间唯一标识一个请求
2.同一个应用内不同并发线程唯一标识一个请求
比如我们可以通过下面一个GUID追踪的一个请求完整的过程
careyson@CareySonMac log % grep "C97E2488-170A-4D01-8B90-BE562FD78342" xxx.log
2021-11-30 16:44:52,725 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] XXX Start
2021-11-30 16:44:53,009 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Begin Instance Rule Check [source version=, target version=]
2021-11-30 16:44:53,010 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] rule check passed. [source version=, target version=]
2021-11-30 16:44:53,011 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Starting check config
2021-11-30 16:44:53,078 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Check config Complete
2021-11-30 16:44:53,079 [WARN] ModifyDBInstanceVersionImpl(46) - [C97E2488-170A-4D01-8B90-BE562FD78342,yunji-dbsingle2,ModifyDBInstanceVersion] Starting get Source Custins info
.....
变量值与常量值分开
将变量值与常量值分开可以使得日志更容易阅读,无论在代码还是日志本身的搜索也会变的简单,如果用工具抽取参数值也变的简单,下面是一个示例:
如果URL是一个很长的串,那么阅读的体验将会非常糟糕。
区分Warn与Error
日志按照严重性同样也会分级,业界标准使用最多的还是Info、Warn与Error。Info通常没什么说的,程序符合预期正常工作,在过程中记录相关信息,就是Info,Warn和Error值得提一下。
Warn意味着程序正常工作,但存在一些问题,这种问题通常在我们预期之内。
Error意味着程序异常,且这种异常不在我们预期内。
下面是一个程序中调用其他服务的简单例子:
如果可能,出错时附上KB或错误代号
写程序的人通常对程序所代表的业务有一定了解,但其他日志用户可能并没有背景知识以及业务限制,在有限的日志中通常很难说清楚,如果有对应KB或帮助文档,以及错误代号,可以附在日志中,帮助日志用户快速了解背景。比如下面这个例子:
避免记录敏感信息
日志并不会像数据库那样有高安全等级,也就是访问日志的安全权限通常远远低于其他应用,且今天的日志更多是上传后中心化,更无法控制日志的扩散范围,因此对于敏感信息请不要记录,包括密码信息、Security Token信息、敏感身份信息等。
使用英文记录日志
英文记录不仅仅是标准化和易于阅读的问题,而是今天的IT系统,日志可能经过多个系统中心化,这些系统只要有一个不支持UTF格式,就可能导致乱码,使用英文可以尽量避免这些麻烦。
小结
对于程序来说,代码质量除了代码本身,还包括日志。将日志当做程序的第二UI认真对待,不仅能使得我们的程序调试与开发成本大幅下降,还能使得程序的运维排错更加简洁,Bug更早发现。