关于日志打印的几点建议以及非最佳实践
日志的打印在软件开发过程中必不可少,一般分为两个大类:
- 操作日志
- 系统日志
操作日志,主要针对的是用户,例如在Photoshop软件中会记录自己操作的步骤,便于用户自己查看。
系统日志,主要针对的是软件开发人员(包括测试、维护人员),也就是说这部分的日志用户是看不到的,也就是我们通常所说的debug日志。
在大学中所谓的实践项目或者老师布置的作用中,通常是不会在意日志,除非在作业中有特别的需要,往往在开发过程中直接打印控制台语句来调试程序,这是极为不专业的调试开发过程。所以这也就导致了一个问题,大学毕业和工作时衔接不上最大的问题不在于技术上的难度,而是日志打印的问题。这个看似不起眼的问题对于应届生来说往往是“恶梦”,操作日志相对比较好理解,用户做了什么就记录什么;而打印系统日志则无从下手,往往一般有下面几个方面——3W:
- Where:不清楚在何处打印日志
- Who:不清楚打印什么级别的日志
- What:不清楚日志应该包含什么内容
本篇着重讲解系统日志,所以以下“日志”均为“系统日志”的简称。我将针对这几个方面对系统日志的打印做一个简要的总结。另外对Java中常用的日志打印框架(log4j)的几种使用方式做一个示范。
WHERE
1.程序入口
在入口打印日志是因为这个时候传递进来的参数没有经过任何处理,将它打印在日志文件中能一眼就知道程序的原始数据是否符合我们的预期,是不是传递进来的原始数据就出现 的问题。
2.异常捕获
在异常打印出详细的日志能让你快速定位错误在哪里,例如在程序抛出异常捕获时,在平时我们经常就是直接在控制台打印出堆栈信息e.printStackTrace(),但在实际的生产环境更加艰苦,更别说有IDE来让你查看控制台信息,此时就需要我们将堆栈信息记录在日志中,以便发生异常时我们能准确定位程序在哪里出错。
3.重要信息
这一点可能很宽泛,因为不同的业务逻辑重点可能并不一样,例如在有的重要参数不能为空,此时就需要判断是否为空,如果为空则记录到日志中;还有的例如传递进来的参数经过一系列的算法处理过后,此时也需要打印日志来查看是否计算正确。但切记,尽量不要直接在for循环中打印日志,特别是for循环特别大时,这样你的日志可能分分钟被冲得不见踪迹,甚至带来性能上的影响。
WHO
日志打印通常有四种级别,从高到底分别是:ERROR、WARN、INFO、DEBUG。应该选用哪种级别就是个很重要的问题。
首先明确日志级别中的优先级是什么意思,在你的系统中如果开启了某一级别的日志后,就不会打印比它级别低的日志。例如,程序如果开启了INFO级别日志,DEBUG日志就不会打印,但不打印不代表不产生,这在后面会提到。通常在生产环境中开启INFO日志。
那么应该打印什么级别的日志呢?首先我们应该明确谁在看日志。
通常来说,系统出了问题客户不会进到系统对着黑黢黢的控制台查看日志输出,所以日志所面对的主体对象必然是软件开发人员(包括测试测试、维护人员)。
下面我们假设几种场景来帮助我们理解日志级别。
首先,程序开发结束后交由给测试人员进行测试,测试人员根据测试用例发现某个用例的输出和预期不符,此时他的第一反应该是查看日志。此时的日志是INFO级别日志不会出现DEBUG级别的日志,现在就需要根据日志打印分为两种情况决定他下一步操作:
- 通过查看INFO日志发现是由于自己操作失误,造成了程序结果和预期不符合,这种情况不是程序出错,所以并不是bug,不需要开发人员到场。
- 通过查看INFO日志发现自己的操作正确,根据INFO日志查看并不是操作失误造成,这个时候就需要开发人员到场确认。
- 以上两种情况是理想情况,测试人员仅根据INFO级别的日志就能判断出程序的输出结果与预期不符是因为自己操作失误还是程序bug。更为现实的情况实际是测试人员并不能根据INFO级别的日志判断是否是自己失误还是程序bug。
综上,INFO级别的日志应该是能帮助测试人员判断这是否是一个真正的bug,而不是自己操作失误造成的。
假设测试人员现在已经初步判断这是一个bug,并且这个bug不那么明显,此时就需要开发人员到场确认。
开发人员到达现场后,第一步应该是查看INFO日志初步作初步判断验证测试人员的看法,接着如果不能判断出问题所在则应该是将日志级别调整至DEBUG级别,打印出DEBUG级别的日志,通过DEBUG日志来分析定位bug出在哪里。
所以,DEBUG级别的日志应该是能帮助开发人员分析定位bug所在的位置。
ERROR和WARN的级别都比INFO要高,所以在设定日志级别在INFO时,这两者的日志也会被打印。根据上面INFO和DEBUG级别的区别以及适用人员可以知道,ERROR和WARN是同时给测试和开发观察的。
WARN级别称之为“警告”,这个“警告”实际上就有点含糊了,它不算错,你可以选择忽视它,但也可以选择重视它。例如,现在一个WARN日志打出这么一条日志“系统有崩溃的风险”,这个时候就需要引起足够的重视,它代表现在不会崩溃,但是它有崩溃的风险。或者出现“某用户在短时间内将密码输出很多次过后才进入了系统”,这个时候是不是系统被暴力破解了呢?等等,这个级别日志如同它的字面含义,给你一个警告,你可以选择忽视,也可以重视,但至少它现在不会给系统带来其他影响。
ERROR级别称之为“错误”,这个含义就更明显了,就是系统出现了错误,需要处理。最为常见的就是捕获异常时所打印的日志。
上面我们介绍了四种日志级别的区别,特别需要注意的是INFO级别和DEBUG级别所适用的人员。那么我们该如何选择哪个级别的日志输出呢?
以下是我的个人理解:
INFO
程序入口,这能让开发人员确认参数是否为自己所为。
计算结果,测试关心的程序的输出结果是否符合预期,那么对于计算过程不应该关心,仅给出计算结果就能判断是否符合预期。
DEBUG
对于DEBUG级别,我认为更关心的是过程,以及更为具体的相关信息,因为帮助它的定位在于帮助开发人员定位bug,定位bug就需要较为详细的参数信息才能定位。例如对于某个具体的算法过程,可以使用DEBUG打印,开发人员不仅关心结果,同时在结果不正确时应该能根据DEBUG日志查询计算过程是否出现偏差
WARN
某个不常走到的分支,对于常规的操作是不应该打印WARN日志的,只有在满足某个条件才能走到的分支,且这个分支引起了“警觉”,此时就应该打印WARN日志。
ERROR
毫无疑问出现错误,程序不能继续运行下去就应该打印ERROR日志,这个错误并不是业务上的错误。例如,新增某个用户发现已经存在时,此时虽然新增失败,但不能说程序出现错误就打印ERROR日志;在删除某个用户发现用户已经被锁定时,此时也不能说因为程序不能按照删除的逻辑继续运行下去就应该打印ERROR日志。
WHAT
应该打印什么内容?打印的内容一定要从实际出发。也就是说如果在实际的生产环境中,你的用户量很大,日志在不停地刷新,如何定位某个用户的整个登录以及后续的操作呢?当然就是根据用户名来跟踪。所以打印内容的第一要素就是要能便于定位;定位过后也许用户在好几个模板中进行操作,还是定位,这个时候定的是模块的位;还有一点当然就是用户操作时的具体参数;最后一点就是用户干了什么。
总结就是