有关写log的思考

前言

在软件开发过程中，log往往是不太引人注意的环节，大部分的log都只是开发人员为了调试bug临时加上的。这样出来的软件，最后的log往往杂乱无章没有系统性。我们判断一个软件系统的log写的好不好，可以通过以下几点：

• 当软件交付给其他人使用出现bug，他们是否能够凭借log对问题有一个比较准确的推断。
• 当开发者解决bug的时候，通过更改不同的log级别是否可以快速准确的定位具体问题所在。
• 当软件生产环境运行时，运维人员能否通过看log就大致了解系统状况和工作情况。

好的log往往各不相同，但是不好的log基本特点都是一样的：

• 描述不清，杂乱无章，大量临时添加的log语句在其中。比如web server log里常见的一行"conntected"，这往往是开发人员开发时为了验证连接是否成功加上的。而且在这个log前后往往还会出现"trying to connect", "connecting ..."，以及"connected to ..."之类的重复。开发人员为了着急完成功能，往往会加入大量这样的log，但是这些log在系统中留下了杂乱的痕迹。
  我们应该尽可能准确丰富的用log表达系统行为，对于刚刚的例子，应该在刚开始连接时加入一个"debug"级别的"connecting Database/Web Admin Server/.. ..."，这里不仅描述了连接url，还描述了连接的server的业务功能，这样如果有很多个连接建立时，log里可以清晰分辨，定义为"debug"级别是因为我们只需要在开发过程和调试bug时知道有这个行为即可，在生产环境中不需要反复提示。然后我们在连接的错误处理中打连接失败的log,"connection to Database/Web Admin Server .. failed, due to ..."。通常情况下，连接成功不用再打log了，因为系统会进行下一步操作。当然也可以加一个“debug”级别的“connection to Database/Web Admin Server .. established"

• 在真正调试bug时，又需要东加一行log，西删一行log。当开发的软件出现问题时，开发人员往往发现以前写的log都用不上，解决问题需要添加很多log才行，而且还要删除很多其它的log免得log太杂乱看不清。这个其实是开发人员的经验不足，在开发过程中预计不到可能出问题的点和解决问题可能需要的条件。比如在写一个与http server以json格式通信的模块时，我们可以先用”debug“级别写一个”send [function] request to Database/Admin server", 这里用“debug”级别同样因为在生产环境时我们可以方便的关掉它，而在debug级别我们又充分描述了系统的行为。但是这样往往是不够的，我们经常会需要了解发送的具体内容进行问题诊断， 所以我们可以在后面加入一个log语句，如果有，最好用更细的级别比如"trival"之类的，记录下log("trival", "request content : " + request.body)。这样我们可以随时把log级别调到trival来详细诊断问题。等等，这样就够了么？其实还不够，如果这么写log，真出先问题的时候你会发现request content非常长，根本不能直观的来观察内容。最好的办法，我们在这里把request.body按照一定的缩进格式打印，变成JSON.stringify(request.body, null, 4)，这样的log就非常直观明了了。

• 层叠的Exception。首先明确一点，Exception是用来帮助解决未知问题的。所以它会有展开的调用栈让我们知道问题出在哪里。而如果一个已经写好的软件系统，是不应该还有未知问题出现的，如果出现了，应该作为bug尽快fix。对于一个完成的软件系统，所有的Exception都应该是被有预计的catch并且处理，然后在处理这个Exception的那一层，用简单明了的log记录下来。

    注：接下来的内容为个人见解，请每个读者独立思考合理和不合理之处。
  

在写log的时候，我们需要结合以下三点来考虑：

• 这个log在系统工作过程中的出现次数
• 这个log适合的级别（生产级别，开发级别和调试级别），对整体log的影响。
• 这个log能表达的信息量，是否跟其它log有重复，是否可以在其它位置写表达更丰富的信息

接下来我们以一个Web系统为例子讲一下log的写法

启动

启动时候，系统需要读取一些配置文件，这个时候需要打印一些读取到的参数之类的，结合上面三点，它的出现次数一般就一次，因此对于级别没有什么要求，就写成info级别即可，表达信息时注意描述准确。

收到请求

在收到请求时，我们可以考虑打一条log表示收到，但是如果系统通讯量很大，这个log的出现次数太多，因此不适合于info级别（info一般是用在生产环境中），通常会定义成debug级别。另外，根据刚刚讲到的，我们经常会需要把收到的request内容打在log中，但是如果把内容整个打印出来会很占篇幅，如果我们是在定位问题和解决其它问题时，这个log干扰有点大。因此我们用debug级别来仅仅描述收到了request，另外再用一个更精细的级别来把请求内容打印出来。

业务逻辑

收到请求后，我们通常要开始业务逻辑，这里参考上面的办法，用”debug"来简要描述各个业务的关键点，而用更细的级别来描述每个点所涉及到的具体数据。注意，info级别因为用在生产环境中，我们通常只需要用info级别描述结果即可，不要用info去描述过程。

错误处理

错误处理有一条很基本的原则：谁处理错误谁打log。这样可以避免大量重复内容的log出现，并且按照前面所说，错误的栈信息通常是不用打印的，处理错误的函数应该能用准确的语言归纳描述错误原因和处理办法。

后记

软件系统好比一个妹子，功能，UI之类的是妹子的外表，往往会第一时间吸引人。但是用户体验(...为毛我有奇怪的联想），log这些东西是内在的品性。这些是真正能让人觉得好用(....呃）的点，也是能真正体现出设计者内功差异的地方。
好吧，你就是只看外表，不求朝朝暮暮就要一晌之欢？。。呃......