软件系统的黑匣子:我们要怎样写日志

引言

作为一个软件系统,需要写日志,这是不言而喻的,这是大家都会不假思索地说“那当然”的事。不论是什么语言,写日志的专用框架也不一而足,写到文本的,写到数据库的,写到队列的,写到Redis的等等等等。对于日志的几个级别,Trace、Debug、Warning、Error、Fault,大家也能够如数家珍。但是,有多少人能够回答下面这几个问题呢?

为什么需要写日志?
什么时候写日志?
日志是写给谁看的?
日志里都要写什么?
日志的组织形式应该怎样?

接下来,我尝试一一地解答这些问题,说说我的理解。

为什么需要写日志

首先我们要树立一个观点,那就是“不是为了记录日志而记录日志,日志也不是随意记的”。要实现能够只通过日志文件还原整个程序执行的过程,达到能透明地看到程序里执行情况,每个线程每个过程到底执行到哪的目的。日志就像飞机的黑匣子一样,应当能够复原异常的整个现场乃至细节。

作为程序员,我相信吐槽写注释、写文档的段子已经见得很多了。然而在我看来,写日志的重要性完全不亚于前两者,甚至在很多时候,比前两者更为重要。

我们说“软件工程”,很多人只着眼了“软件”两个字,而忽视了“工程”。软件本身是为解决问题服务的,作为一项工程,我们不单要考虑软件本身的开发环节(注释、文档),还应当考虑软件的运营环节(日志)。世界上没有100%完美的事,不存在没有 bug 的软件系统,一旦软件上线,作为开发人员的我们,就不再能够接触到了,如果系统发生了异常,我们却又对系统运行的状态一无所知,那我们就完全没有办法解决问题。有时候重启一下应用,重启一下系统什么的,也能临时解决,但这只是掩耳盗铃,该来的还会再来,出现过的异常,还会在某一天再次出现。

这个时候对“日志”的需求便应运而生。通过日志,记录程序在运行过程中的细节,记录发生异常时的现场,我们便能像庖丁解牛一样,对运行中的应用了如指掌了。

什么时候写日志

所谓“麻雀虽小五脏俱全”,当我们在建构一个软件系统框架时,所谓的几层结构,所谓的基础模块(通用模块、工具模块、数据访问模块……),包括写日志的模块,这些方法都是不用思考,放之四海而皆准的东西,直接搭建/拼凑起来再说。

然后呢?我想很多人就开始闷头做功能了——我是指只写功能代码,完成实际的业务逻辑。在做业务功能的时候,由于现代IDE的调试功能很强大,可以一行一行调试,看到运行状态、变量状态等等,所以此时对日志的需求和功用是极度不敏感,觉得此时可有可无。但是一旦业务功能做完了,基于各种各样的理由,工期紧啊,已经完成功能了啊,就直接转测不再继续完善了。其结果是,功能的确完成了,但是搭建的日志模块却几乎没有使用。完成了整个系统,只有不痛不痒的两三行日志,大多都是在搭建框架时写的“应用启动了”,“应用停止了”一类。后面就不用说了,都说回头补设计文档,有多少人补了?都说回头补注释,有多少人补了?既然已经转测了,既然已经上线了,就更不会再回头去写日志了。

后来,可想而知,当生产环境除了问题,由于没有日志,到底出了什么异常,就两眼一抹黑,没人能知道了。终于,临时解决了问题,意识到日志的重要性之后,急急回头翻出代码来写日志,可是当时做业务的逻辑、思考、陷阱、注意事项等等,都忘记的差不多了,写日志也就只能像看陌生代码一样,看表面,“进入了XXX方法”,“插入数据库完成”,只能写这样的日志了。而在我看来,这样的日志是不够的,这也是我最反感的写日志的方式,完全是为了写而写——也是不足以还原故障现场的,这个后续再说。

说到此可能你应该也看出来的,什么时候写日志是最佳时机呢?那就是在开发功能代码时。可以说,日志本身也是属于功能代码的一部分,只不过业务功能是给最终客户的,而日志是给运维、开发等用的。此时写日志有一个巨大的好处,那就是因为你是一边在思考,一边在开发,那么此时业务流转、可能的异常都会考虑得很完善,写日志的过程,也是反复思考和校验逻辑的过程,也就自然而然地会在日志中体现更多的关键信息。

日志是写给谁看的

  • 当然是给运维了啊,运维能够第一时间看到,比如日志中写端口被占用,马上改个端口就可以了!
  • 当然是给开发了啊,每次系统发生了异常,运维人员不是直接把日志给开发人员一丢就了事了吗?

在我看来,不论是运维,还是开发,再广泛地讲,包括白盒测试,都是需要看日志的。日志对不同的人,都有不同的使用价值。运维通过日志了解到程序基本的安装、环境依赖、加载情况、运行态信息等等;开发通过日志还可以了解到程序对业务处理的信息,每个业务的流程、环节、现场状态等等;白盒测试也可以通过日志了解到程序要求的非功能特性等等。

日志里都要写什么

明确了“为什么要写日志”和“日志写给谁看的”了之后,要回答“日志里都要写什么”就容易得多了。我们需要从多个侧面来想这个问题。

考虑使用者

正如前文说,日志可能面向运维、面向开发等等不同身份的人群。因此日志的内容上,就要为不同的人写入其关切的入不同内容。

考虑业务

这里的“业务”可能不一定是最终用户的业务,也可能是中间态的业务逻辑。当业务处理出现问题时,到底是程序的bug造成,还是错误的数据造成,或者是硬件、网络等资源的问题造成,这些都应当能够从日志中分析得出来。

一段日志,应当能够对故障现场的每一个细节都能在大脑思维里复盘。同时,日志不单单像流水账一样记录程序的运行过程,每行日志还不应该是孤立的,还应当是一个有机的整体,是有上下文的,有头有尾的。比如下面这一段日志:

log-example

日志中记录了一些关键事件以及一些关键信息。比如什么时候侦测到了新消息,有几个Handler可以去处理,每个Handler对应了哪个线程,每个线程对应在处理那种消息;有了某个处理过程的开始,就应当有对应的结束,如果涉及到多线程,还应当能够区分两行同样的日志,对应的不同线程和不同业务单据等等。而不仅仅是“侦测到消息”,“开始处理”,“处理完毕”这种简单的记录。

考虑运营

对于业务,一般我们需要后续的分析和运营,日志在这方面也有起到较大作用,因此这部分日志应当考虑以结构化、规范化的方式来记录,从而方便后续对日志进行自动化分析。

考虑生命周期

那么日志是越详细越好,记录得越多越好吗?是。也不是。

每一个软件系统都是有一定的生命周期的。刚测试上线的软件,一般最不稳定,最容易出现各种这样那样的问题,此时日志应当详细些。而长期运行了很久的软件,经过了时间、业务的大量考验,该出现的bug也已经修复得差不多了,几乎不会再出现什么问题,日志应当少一些。

怎么实现呢?很显然我们不能通过改代码,去掉写日志的代码之后重新发布来做这件事。常规地,我们通过日志分级来应对这个问题。通过不同的日志分级,以及日志输出开关,实时地调整日志输出的细节程度。因此,在我们编写输出日志的代码时,就务必要注意即将输出的日志应当是什么级别。Trace、Debug、Warning、Error、Fault,这些级别,应当对应不同重要程度、不同使用场景的细节。

考虑了以上三个方面,在开发完成之后,我们还应当切换不同的身份、角度以及配置不同的日志输出级别,来“设身处地”地审视输出的日志文件,是否能够满足要求,这样才能写一份好的日志记录。

日志的组织形式应该怎样

既然叫“日志”,那我们通常的组织形式变是以时间为顺序来组织的一系列文件。除此之外,还可以将日志写入数据库、外部分析系统等等。

考虑“Separation of Concerns”,日志的组织形式,也可以根据上文考虑的不同方面来组织,比如将Error及以上的日志冗余独立记录,将面向运维的启停、加载信息独立记录,将软件运行日志和业务处理日志分开记录等等。关键是“Concern”,编写记录日志的代码时,我们应该对这段代码的功能、重要性、在整个系统的角色有深刻的认知,从而才能以不同的“关切”来考虑日志应该怎么输出,怎么组织。

综上

当然,根据软件系统的不同,其日志的侧重点也可能不同。但总体来说,日志就如同飞机的黑匣子一样重要,我们应当重视日志输出的编写工作,而绝非仅仅是完成核心业务代码的编写。